Debug Trace


If you want to hack or debug Rockhopper VPN software, debug trace service and related tools are useful.

- Per-process debug trace (default)


To enable this service, please add the dbg_use_trace_file setting on the Global Configuration tab of Web console.

This default debug trace service is not very handy and not very fast. Actually, extended debug trace service is more useful to debug Rockhopper VPN software.


- Global Configuration[Tab] > Global Settings[Tab]

  1. Click VPN's Settings button and show Add a New Global Setting (VPN) dialog.

  2. Setting Name: Select dbg_use_trace_file.

  3. Setting Value: Enter 1 to enable this service. When disabling it, please enter 0.

  4. Click OK button.

  5. Click Save Configuration button.

  6. Restart Rockhopper like this (Ubuntu):

    # sudo /etc/init.d/rockhopper restart
    or
    # sudo systemctl restart rockhopper

You can also specify the max size of debug trace in bytes by adding the dbg_trace_file_max_bytes setting. The default size is 20000000(20M) bytes. If the amount of trace records reaches the max size, the oldest records are deleted.

Each process writes trace records to a file (/home/rhpmain/rockhopper_main.trc or /home/rhpprotected/rockhopper_syspxy.trc) in binary format. To see the trace records, please use output2.sh.

# cd <install_dir>/rockhopper-<version>/debug_tools
# sudo /etc/init.d/rockhopper stop (Ubuntu)
or
# sudo systemctl stop rockhopper
# sudo ./output2.sh

In the same directory, output_main.txt and output_syspxy.txt are created. You can see the files' contents by text editor you like. Text-formatted trace records in each file are like this:


A text-format of each trace record:

(No.) YYYY/MM/DD HH:MM:SS-MSEC ["trace-user-label"] "trace-user-id"-"trace-id" p:"process-id",t:"thread-id" ("trace-id-tag") "trace-data"
["source-file":"line-no"]

  ...

(733) 2012/06/23 11:59:13-790394 [mainfreq] 6-3712 p:1336,t:1372 
(esp_impl_rx_decap_ipv4_ip_ip) tls_cache: 0x9ec80d8 pkt: 0x9bddf80 dec_out_p[LEN: dec_data_len]: 
[0x9ec7f30]  80(bytes)
*0 *1 *2 *3 *4 *5 *6 *7 *8 *9 *A *B *C *D *E *F     0123456789ABCDEF
45 00 00 4e 00 0d 00 00 80 11 15 d6 c0 a8 64 14     E..N..........d.
 ...
 pad_len: 0
[rhp_esp_impl.c:1211]

 ...

(725) 2012/06/23 11:59:13-790280 [mainfreq] 6-3717 p:1336,t:1372 
(esp_impl_rx_decap_ipv4) pkt: 0x9bddf80 tls_cache: 0x9ec80d8 seqh: 0 seqh: 0x0 
next_header_r: 0xb57645dc
[rhp_esp_impl.c:1268]


(726) 2012/06/23 11:59:13-790292 [mainfreq] 6-3302 p:1336,t:1372 
(openssl_encr_aes_cbc_get_iv_len) encr: 0x9ec6ca0 AES_BLOCK_SIZE: 16
[rhp_openssl_crypto.c:1441]


(727) 2012/06/23 11:59:13-790303 [mainfreq] 6-3303 p:1336,t:1372 
(openssl_encr_aes_cbc_get_block_len) encr: 0x9ec6ca0 AES_BLOCK_SIZE: 16
[rhp_openssl_crypto.c:1447]


(728) 2012/06/23 11:59:13-790315 [mainfreq] 6-3267 p:1336,t:1372 
(openssl_integ_hmac_sha1_96_get_output_len) integ: 0x9ec8250 12: 12
[rhp_openssl_crypto.c:1007]


(729) 2012/06/23 11:59:13-790326 [mainfreq] 6-3719 p:1336,t:1372 
(esp_impl_rx_decap_ipv4_esp_pkt) pkt: 0x9bddf80 tls_cache: 0x9ec80d8 pkt->data[LEN: pkt->len ]
[PROTO: MAC_IPV4_ESP ][IV_LEN: iv_len][ICV_LEN: icv_len] PROTO: 6 , IV LEN:16 , ICV LEN:12 , 
DATA LEN:158

==<MAC>==
dst_addr : 00:00:00:00:00:00
src_addr : 00:00:00:00:00:00
protocol : 0x800 (ARP:0x0806,IPv4:0x0800,IPv6:0x86DD,)

==<IPv4>==
IHL : 5
Version : 4
TOS : 0x0
total_len : 144
id : 0
frag : 0x0
TTL : 0
Protocol : 17 (ICMP:1,UDP:17,TCP:6,ESP:50,AH:51)
checksum : 0x0
src_addr : 10.0.0.10
dst_addr : 192.168.0.100

==<UDP>==
src_port : 8372
dst_port : 4500
len : 124
checksum : 0

==<ESP>==
spi : 3704306518(0xdccb3b56)
seq : 14

[IV] [0x0]  16(bytes)
*0 *1 *2 *3 *4 *5 *6 *7 *8 *9 *A *B *C *D *E *F     0123456789ABCDEF
41 b8 70 1f 66 c6 c6 8c 86 91 54 26 85 ad 1d 5d     A.p.f.....T....]

[Encrypted Data] [0x0]  80(bytes)
*0 *1 *2 *3 *4 *5 *6 *7 *8 *9 *A *B *C *D *E *F     0123456789ABCDEF
64 aa 97 1f 8c 83 12 9d 71 08 e4 10 34 41 12 c2     d.......q...4A..
a4 36 79 91 12 a9 67 11 97 09 a6 67 0c bc 0b ac     .6y...g....g....
 ...

[ICV] [0x0]  12(bytes)
*0 *1 *2 *3 *4 *5 *6 *7 *8 *9 *A *B *C *D *E *F     0123456789ABCDEF
4a d5 1a 55 c6 18 d8 d9 82 ee bc 64                 J..U.......d

[TRF](ESP)  11:59:13-790326 p:1336,t:1372    
10.0.0.10 >> 192.168.0.100 Len: 144:UDP[8372 >> 4500] NATT [ESP]  SPI(3704306518, 0xdccb3b56) 
SEQ(14) Len: 116

==<DUMP>==

[0x0]  158(bytes)
*0 *1 *2 *3 *4 *5 *6 *7 *8 *9 *A *B *C *D *E *F     0123456789ABCDEF
00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00     ..............E.
 ...

(736) 2012/06/23 11:59:13-790438 [mainfreq] 6-3716 p:1336,t:1372 
(esp_impl_rx_decap_ipv4_ip_ip_rtrn) tls_cache: 0x9ec80d8 pkt: 0x9bddf80 diff: 38
[rhp_esp_impl.c:1247]

 ...




- Extended debug trace service


By installing this additional service, you can get more advantages:
  • Writing trace records faster.
  • All processes (a main process, a protected process and scripts invoked by Rockhopper) and their threads write their trace records to a common buffer, so you can easily debug interaction and timing problems between them.
  • By using the rhp_trace command, you can manage behavior of debug trace service.
  • This extended service also provides kernel-level API to write trace records to the common buffer. When you need to debug interaction or behavior between Rockhopper and kernel services like network stacks, you can embed the API into Linux kernel's source codes.


By default, the service and related tools are NOT installed. To install them, you need to use a different installer script install_dbg.sh.

When you install the debug trace service, it is recommended to install Rockhoper on a computer for debugging purposes only.

- Installed components:

  • rhp_trace_helper: A daemon providing trace flags' status for processes and threads which use Debug trace service.
  • rhp_trace.ko: A kernel module providing a cyclic on-memory buffer into which all processes and threads write trace records.
  • librhptrace.so : A Debug trace library user processes link.
  • rhp_trace_load script: A script file invoked by /etc/init.d/rockhopper script to start or stop Debug trace service. The Debug trace service starts before Rockohpper daemon processes are invoked.
  • rhp_trace: A command-line tool to manage Debug trace service.

Before installing Rockhopper with these components by install_dbg.sh, you may need to install kernel headers to build rhp_trace.ko like this:
   # sudo apt-get install linux-headers-`uname -r` (Ubuntu)
   or
   # sudo yum install kernel-devel (CentOS)

- Install Rockhopper VPN package with Debug trace service and tools:

  1. Download the same software's package(rockhopper-<version>.tgz).
  2. tar zxvf rockhopper-<version>.tgz
  3. cd rockhopper-<version>
  4. sudo ./install_dbg.sh       *:Run the installer script as root.
  5. Finally, reboot your system.

- Use Debug trace tools

By default, all trace user's flags are enabled by rhp_trace_load script. To see the Debug trace status, please use rhp_trace command like this:

   # sudo rhp_trace -i
    Buffer:00099850 bytes / 10000000 bytes (used / total).
    [1] common       : mask[255] : ENABLED
    [2] syspxy       : mask[255] : ENABLED
    [3] main         : mask[255] : ENABLED
    [4] func         : mask[255] : ENABLED
    [5] trace_file   : mask[255] : ENABLED
    [6] main_freq    : mask[255] : ENABLED
    [7] syspxy_freq  : mask[255] : ENABLED
    [8] reserved     : mask[255] : ENABLED
    
The labels like "common" and "syspxy" are names of trace users.

The trace buffer already stores some trace data. To see the data, please use output.sh.

# cd <install_dir>/rockhopper-<version>/debug_tools
# sudo ./output.sh

In the same directory, a text file output.txt is created. You can see the file's contents by text editor you like. Text-formatted trace records in the file are like this.


- What does the output.sh script actually do?

output.sh is a mere wrapper script and it calls rhp_trace command internally. First, rhp_trace retrieves trace data from the trace buffer managed by rhp_trace.ko. This trace data include all trace records generated by Rockhopper's processes and threads in binary format. Next, rhp_trace translates the binary data into text data by using formatter files. There are several formatter files like rhp_trc_main.xml and rhp_trc_syspxy.xml in the same directory.


- Debug trace management by rhp_trace command


Use '-h' option to know what this command do.
                
# rhp_trace -h
 -e user_id [filter_mask] : enable trace
 -d user_id : disable trace
 -s output_file : save trace
 -t output_file xml_file ... : translate trace
 -z size : set trace size(byte)
 -r : reset trace
 -i : show trace configuration

Command examples:
;Enable a trace user "main".
# sudo rhp_trace -e main 

;Disable a trace user "main". Trace records of this user will not be stored anymore.
# sudo rhp_trace -d main

; Resize debug trace buffer to 1M bytes.
# sudorhp_trace -z 1000000

; Clear debug trace buffer.
# sudo rhp_trace -r





- Add a debug trace code in a source file

Debug trace API is defined in rhp_trace.h. Please read the include file to understand the API's details. Actually, when you add a new debug trace code in a Rockhopper's C source file, please use RHP_TRC macro defined in rhp_misc2.h. To understand the actual usage of this macro, please read source files.

[NOTICE]
  • All arguments of the RHP_TRC macro must be written in a single line.
  • If you create a new C source file, the file name must be globally unique in the Rockhopper package.
  • If you define a new trace label for the conversion specifier 'L', which can be specified in the format argument of rhp_trace() function or RHP_TRC macro, please update bsym.def or msym.def in <install_dir>/rockhopper-<version>/rockhopper/misc/, too. bsym.def is for the conversion specifier 'B' and msym.def is for other conversion specifiers like 'w', 'd', 'q', etc.

After you add, update or delete a debug trace code or you update a C source file, you need to generate include files, rhp_main_traceid.h and rhp_main_traceid_str.h, which define trace record's IDs, and formatter files(rhp_trc_XXX.xml) by mk_trace_fmt.sh script.

# cd <install_dir>/rockhopper-<version>/rockhopper/misc
# ./mk_trace_fmt.sh

The generated include files, rhp_main_traceid.h and rhp_main_traceid_str.h, are copied to <install_dir>/rockhopper-<version>/rockhopper/include directory. Now you can build Rockhopper's updated source files. And output.sh can translate your new trace code into a formatted text by using updated formatter files(rhp_trc_XXX.xml). These formatter files are also copied to the <install_dir>/rockhopper-<version>/debug_tools directory where the above output.sh is placed.





Back to Top