Problem:

• Product Name: VisiBroker 
• Product Version: All
• Platform/OS Version: all

How to read GIOP message and correlate request and reply from VisiBroker logs?

Resolution:

CORBA 3.0 specification states that Request Message is composed of the following:

• A GIOP Message Header
• A Request Header
• A Request Body

while the Reply Message is composed of the following:

• A GIOP Message Header
• A ReplyHeader structure
• A Reply Body

A Request and Reply Header contains request_id which is used to associate reply messages with request messages.

The Request Message

When client process sends a Request Message, it looks something like this on VisiBroker logs using the vbroker/basic/bank_agent example:

For C debug logs:

Pid# 5668 Tim# Sat Aug 01 06:28:15 2009 374000ms Tid# 7716 src="http://files.microfocus.com/filemanager/files/kb/Borland/BorlandKB/18876/>writtentounderlying connectionfromGIOPoutput0x00B67AB0
GIOP version :- 0x102
GIOP 1.2 wchar :- 0x1
byte order :- 0x1
host byte order :- 0x1
start offset :- 0x92
data offset :- 0x80
current offset :- 0x92
release flag :- 0x1
Dsz# 146 Dat#
0 1 2 3 4 5 6 7 8 9 A B C D E F
00B49120 47494F50 01020100 86000000 02000000 GIOP .... .... ....
00B49130 03000000 00002020 2B000000 01504D43 .... .. ... .PMC
00B49140 04000000 10000000 2F62616E 6B5F6167 .... .... /ban k_ag
00B49150 656E745F 706F6100 0B000000 42616E6B ent_ poa. .... Bank
00B49160 4D616E61 67657220 05000000 6F70656E Mana ger .... open
00B49170 00202020 02000000 01000000 0C000000 . .... .... ....
00B49180 01202020 01000100 09010100 06534956 . .... .... .SIV
00B49190 06000000 01070801 83002020 20202020 .... .... ..
00B491A0 0E000000 4A61636B 20422E20 51756963 .... Jack B. Quic
00B491B0 6B00 k.

In above data, the first 12 bytes comprises the GIOP Message Header which will be described briefly below as we traverse through the bytes until request_id byte:

• The first 4 bytes [47494F50] is the magic which identifies a GIOP message. In the specifications, it is always "GIOP"
• The next 2 bytes [0102] is the GIOP version, where 0x0100 is v1.0, 0x0101 is v1.1, and 0x0102 is 1.2 (which is used in this example). Note that VisiBroker 8.0 complies with CORBA 3.0 except the CORBA Component Model (CCM) and GIOP 1.3 (refer to release notes).
• The next byte [01] is the flag. 0x00 means big-endian while 0x01 means little-endian byte ordering. Note that the GIOP version 1.2 is used, hence, byte_order attribute is not applicable and shown. Our client or requester is running on a little-endian computer (01).
• The next byte [00] is the message type. 0x00 means "Request" and 0x01 means "Reply". See Table 15-3 of CORBA 3.0 Specification describes the complete message types and originators.
• The next 4 bytes [86000000] is the message size; in this case: 134 (0x86) bytes. Note the little-endianness of 86000000 and bytes are shifted first then converted to decimal representation: 134.
• The next 4 bytes (an unsigned long or CORBA::ULong) is the request_id, which is 0x02000000 (little-endian). When the client is waiting for a reply (tagged "req_id = 2"), the debug logs look something like this:

Pid# 5668 Tim# Sat Aug 01 06:28:15 2009 452000ms Tid# 7716 src="http://files.microfocus.com/filemanager/files/kb/Borland/BorlandKB/18876/>req_id=2

The Reply Message

When the client received the reply, the ORB reads the first 12 bytes which is the GIOP Message Header (format is the same described above):

Pid# 5668 Tim# Sat Aug 01 06:28:15 2009 452000ms Tid# 7716 src="http://files.microfocus.com/filemanager/files/kb/Borland/BorlandKB/18876/>readfromunderlying connectiontoGIOPinput0x00B68CF0
GIOP version :- 0x102
GIOP 1.2 wchar :- 0x1
byte order :- 0x1
host byte order :- 0x1
start offset :- 0x0
data offset :- 0x0
current offset :- 0x0
release flag :- 0x1
Dsz# 12 Dat#
0 1 2 3 4 5 6 7 8 9 A B C D E F
00B75F98 47494F50 01020001 000000F8 GIOP .... ....

Note that the message type [ 01 ] (the 8th byte) is a Reply Message and is sent from a big-endian computer [ 00 ]. Now that we know that this is a Reply Message, we will correlate this reply to the previously sent Request Message.

The ORB then reads the remaining message size which is 248 [ 0x000000F8 ]bytes:

Pid# 5668 Tim# Sat Aug 01 06:28:15 2009 484000ms Tid# 7716 src="http://files.microfocus.com/filemanager/files/kb/Borland/BorlandKB/18876/>readfromunderlying connectiontoGIOPinput0x00B68CF0
GIOP version :- 0x102
GIOP 1.2 wchar :- 0x1
byte order :- 0x0
host byte order :- 0x0
start offset :- 0xc
data offset :- 0x0
current offset :- 0xc
release flag :- 0x1
Dsz# 248 Dat#
0 1 2 3 4 5 6 7 8 9 A B C D E F
00B49420 00000002 00000000 00000000 00000015 .... .... .... ....
00B49430 49444C3A 42616E6B 2F416363 6F756E74 IDL: Bank /Acc ount
00B49440 3A312E30 00202020 00000002 56495301 :1.0 . .... VIS.
00B49450 0000004D 00010220 0000000C 73677264 ...M ... .... sgrd
00B49460 732D7473 73313000 0000736D 00000000 s-ts s10. ..sm ....
00B49470 0000001C 00564201 00000002 2F002020 .... .VB. .... /.
00B49480 00000001 30202020 4A736F0E 00059CF3 .... 0 Jso. ....
00B49490 00000001 56495303 00000005 00070801 .... VIS. .... ....
00B494A0 83202020 00000000 0000006C 00010220 . .... ...l ...
00B494B0 00000010 3134332E 3138362E 3133392E .... 143. 186. 139.
00B494C0 31373700 27112020 0000001C 00564201 177. ". .... .VB.
00B494D0 00000002 2F002020 00000001 30202020 .... /. .... 0
00B494E0 4A736F0E 00059CF3 00000002 56495303 Jso. .... .... VIS.
00B494F0 00000005 00070801 83202020 00000001 .... .... . ....
00B49500 00000014 00202020 00010001 00000000 .... . .... ....
00B49510 00010109 00000000 .... ....

We read the request_id as 0x00000002 (from a big-endian computer) and correlate it with the previously sent request_id as 0x02000000 (from a little-endian computer).

For Java, the Request Message looks like the following and the request_id is correlated with [ 00 00 00 02 ]:

08:20:08,030 [main] Debug VBJ-Application.orb_com.inprise.vbroker.orb.ORB@1b16e52.vbroker.log.default.filter.cdr - 143.186.141.082,00006184,

****** Sending Message *****
47 49 4F 50 01 02 00 00 00 00 00 00 00 00 00 02 GIOP............
03 00 00 00 00 00 00 00 00 00 00 2B 00 50 4D 43 ........... .PMC
00 00 00 04 00 00 00 10 2F 62 61 6E 6B 5F 61 67 ......../bank_ag
65 6E 74 5F 70 6F 61 00 00 00 00 0B 42 61 6E 6B ent_poa.....Bank
4D 61 6E 61 67 65 72 00 00 00 00 05 6F 70 65 6E Manager.....open
00 00 00 00 00 00 00 02 00 00 00 01 00 00 00 0C ................
00 00 00 00 00 01 00 01 00 01 01 09 56 49 53 06 ............VIS.
00 00 00 05 00 07 08 01 83 00 00 00 00 00 00 00 ................
00 00 00 0E 4A 61 63 6B 20 42 2E 20 51 75 69 63 ....Jack B. Quic
6B 00 k.

However, the message size [ 00 00 00 00 ] is not displayed for Java logs, but can be confirmed correctly in the WireShark.

And the Reply Message as:

08:20:08,187 [main] Debug VBJ-Application.orb_com.inprise.vbroker.orb.ORB@1b16e52.vbroker.log.default.filter.cdr - 143.186.141.082,00006184,

****** Received Message *****
47 49 4F 50 01 02 00 01 00 00 00 F8 00 00 00 02 GIOP............
00 00 00 00 00 00 00 00 00 00 00 15 49 44 4C 3A ............IDL:
42 61 6E 6B 2F 41 63 63 6F 75 6E 74 3A 31 2E 30 Bank/Account:1.0
00 20 20 20 00 00 00 02 56 49 53 01 00 00 00 4D . ....VIS....M
00 01 02 20 00 00 00 0C 73 67 72 64 73 2D 74 73 ... ....sgrds-ts
73 31 30 00 00 00 73 6D 00 00 00 00 00 00 00 1C s10...sm........
00 56 42 01 00 00 00 02 2F 00 20 20 00 00 00 01 .VB...../. ....
30 20 20 20 4A 73 6F 0E 00 05 9C F3 00 00 00 01 0 Jso.........
56 49 53 03 00 00 00 05 00 07 08 01 83 20 20 20 VIS..........
00 00 00 00 00 00 00 6C 00 01 02 20 00 00 00 10 .......l... ....
31 34 33 2E 31 38 36 2E 31 33 39 2E 31 37 37 00 143.186.139.177.
27 11 20 20 00 00 00 1C 00 56 42 01 00 00 00 02 ". .....VB.....
2F 00 20 20 00 00 00 01 30 20 20 20 4A 73 6F 0E /. ....0 Jso.
00 05 9C F3 00 00 00 02 56 49 53 03 00 00 00 05 ........VIS.....
00 07 08 01 83 20 20 20 00 00 00 01 00 00 00 14 ..... ........
00 20 20 20 00 01 00 01 00 00 00 00 00 01 01 09 . ............
00 00 00 00 ....