Debugging and Tracing with OCI GoldenGate

Data Voyage by Jigar Doshi
Oracle Developers
Published in
11 min readMay 15, 2023

How to debug OCI GoldenGate using console and adminclient

Debugging is both an art and science. With any software, there is a time when we need to dive deeper into internals instead of working on the surface. OCI GoldenGate provides multiple channels like adminclient command line utility, Web console, REST API, SDK etc. to operate and manage the cloud native service.

In this article, I will discuss some of the debugging techniques which are really helpful when troubleshooting real world scenarios using different OCI GG management tools.

Debugging with adminclient

My preferred mode of operating and managing OCI GG is via adminclient. You can read more about adminclient here. Debugging with adminclient is very easy and only needs one command.

SET DEBUG ON

Let’s look at an example of debugging with adminclient. I have executed same command with DEBUG OFF AND ON. With DEBUG mode OFF, we can see plain vanilla output that is fairly readable.

OGG (https://abcddeployment....com OCIGGTestDeployment) 6> STATS REPLICAT RNOPK

Sending STATS request to Replicat group RNOPK ...


Parallel Replicat statistics:


*** Total statistics since 2023-04-12 08:32:48 ***
No transactions yet processed.

*** Daily statistics since 2023-05-13 00:00:00 ***
No transactions yet processed.

*** Hourly statistics since 2023-05-13 18:00:00 ***
No transactions yet processed.

*** Latest statistics since 2023-04-12 08:32:48 ***
No transactions yet processed.

Start of statistics at 2023-05-13 18:00:00.

End of statistics.

Let’s test the same command with DEBUG ON. With debug on, we can see all the rest API calls made by adminclient!!. For some reason adminclient makes GET REST call for all REPLICATS before actually issuing STATS command for RNOPK REPLICAT.

OGG (https://abcddeployment....com OCIGGTestDeployment) 14> SET DEBUG ON
Command 14 succeeded: 'SET DEBUG ON'

OGG (https://abcddeployment....com OCIGGTestDeployment) 15> STATS REPLICAT RNOPK
--------------------------------------------------------------------------------
> GET /services/v2/replicats?threads=all
< Status 200
{
"$schema": "api:standardResponse",
"links": [
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},

Next POST REST call is for the actual STATS command

> POST /services/v2/replicats/RNOPK/command
{
"command": "STATS",
"isReported": true
}
----------------------------------------
< Status 200
{
"$schema": "api:standardResponse",
"links": [
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK/command",
"mediaType": "application/json"
},
{
"rel": "self",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK/command",
"mediaType": "application/json"
}
],
"messages": [],
"response": {
"$schema": "er:commandResult",
"reply": "OKNODOT\t\nParallel Replicat statistics:\n\n\n*** Total statistics since 2023-04-12 08:32:48 ***\n No transactions yet processed.\n\n*** Daily statistics since 2023-05-13 00:00:00 ***\n No transactions yet processed.\n\n*** Hourly statistics since 2023-05-13 18:00:00 ***\n No transactions yet processed.\n\n*** Latest statistics since 2023-04-12 08:32:48 ***\n No transactions yet processed.\n\nStart of statistics at 2023-05-13 18:00:30.\n\nEnd of statistics.",
"replyData": {
"$schema": "ogg:stats",
"stats": [
{

BONUS — This is a good way to learn how to manage OCI GG via REST calls. I often use this to view the expected output and REST call format for writing my own scripts.

Complete output is listed at end of this article for academic reference.

VIEW MESSAGES command can be used to view default ggserr.log

Viewing messages using adminclient

Debugging with Web Console

Another way to debug OCI GG operations is using Web UI console. I use this only when adminclient is not an option or when I am simply lazy. Debugging using Web UI is simple and handy if you are not so comfortable using adminclient. The disadvantage of this approach is that output is extremely verbose. It will trace each and every console navigation and click. This can make reading the output very difficult. Use this only when necessary.

WARNING- Enable this option only for a limited period and preferably when issue can be quickly reproduced. Debug output file can quickly grow very large.

Navigate to “Debug Log” web console menu under administration server. Use the “Enable Debug Log” radio button to enable/disable debug logging. Click “Download Debug Log file” to download and “Delete Debug Log File” to delete the debug output file.

Enabling debug log using OCI GG Web console

I prefer to delete the logfile before starting every new debug session. This helps to contain the output and keep the debug file size manageable.

This is what debug file output (edited for appearance) looks like

2023-05-13 18:59:23.180 Thread 24                     |INFO 
|RestAPI.adminsrvr | 262 StandardResponse.cpp
| Request #8721811: { "context": {
"verbId": 7,
"verb": "PATCH",
"originalVerb": "PATCH",
"unencodedUri": "/services/v2/logs/debug",
"uri": "/services/v2/logs/debug",
"protocol": "http",
"headers": {
"X-OGG-Context": "services/adminsrvr",
"X-OGG-Service": "adminsrvr",
"X-OGG-Version": "v2",
"headers": {
"X-OGG-Version": "v2",
"X-OGG-Resource": "logs/debug",

Navigating to process parameter, connections and routing console navigation, the debug output file grew to 22 MB within < 1 minute. Parsing output from large files can be very difficult. Hence my advice is to use this option only when the problem/error is reproducible very quickly.

TRACING specific EXTRACT/REPLICAT

So far we have discussed on how to enable debugging for OCI GG operations. What if we want to trace specific EXTRACT/REPLICAT process?

For this we can use TRACE/TRACE2 command.

TRACE provides step by step processing information and TRACE2 provides time spent on code segments.

TRACE/TRACE2 command and output file name can be enabled for already running process using SEND command as seen in example below.

Using SEND command tracing can be enable or disabled dynamically without having to restart the process

Enabling runtime tracing for active process

This parameter can also be set in parameter file to enable tracing right from start. To view the trace output, take a manual deployment backup and restore on local machine.

Trace file output


Trace starting at 2023-05-14 Sun UTC 06:59:15

06:59:15.189 (2759195866) IPC_write to /u02/Deployment/var/temp/RNOPK.s() size: 596
06:59:15.189 (2759195866) General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing
06:59:15.192 (2759195869) IPC_read from /u02/Deployment/var/temp/RNOPK.s()
06:59:15.192 (2759195869) calling socket_disconnected from IPC_read_TCP(2) with ip.sock 23
06:59:15.192 (2759195869) closing sock 23
06:59:15.458 (2759196135) IPC_write to /u02/Deployment/var/temp/.RNOPK.A.0.s() size: 75
06:59:15.458 (2759196135) IPC_write to /u02/Deployment/var/temp/.RNOPK.A.0.s() size: 75
06:59:15.458 (2759196135) IPC_write to /u02/Deployment/var/temp/.RNOPK.A.0.s() size: 75
06:59:15.458 (2759196135) IPC_write to /u02/Deployment/var/temp/.RNOPK.A.0.s() size: 75
06:59:15.989 (2759196666) IPC_write to /u02/Deployment/var/temp/.RNOPK.M.0.s() size: 75
06:59:15.989 (2759196666) IPC_write to /u02/Deployment/var/temp/.RNOPK.M.0.s() size: 75
06:59:26.207 (2759206884) entering checkpointPosition
06:59:26.207 (2759206884) exiting checkpointPosition
06:59:31.009 (2759211686) IPC_read from /u02/Deployment/var/temp/RNOPK.s()
06:59:31.009 (2759211686) IPC_write to /u02/Deployment/var/temp/RNOPK.s() size: 1164
06:59:31.009 (2759211686) IPC_read from /u02/Deployment/var/temp/RNOPK.s()
06:59:31.009 (2759211686) calling socket_disconnected from IPC_read_TCP(2) with ip.sock 23
06:59:31.009 (2759211686) closing sock 23
06:59:37.413 (2759218090) IPC_read from /u02/Deployment/var/temp/RNOPK.s()

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:37
* --- entering DataSource::readLCR() --- *
06:59:17.938 (2759191623) * --- entering DataSource::readLCR() --- *
06:59:17.938 (2759191623) General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing
06:59:18.978 (2759193624) * --- entering DataSource::readLCR() --- *
06:59:18.991 (2759192675) * --- entering DataSource::readLCR() --- *
06:59:19.989 (2759194635) * --- entering DataSource::readLCR() --- *
06:59:19.939 (2759193623) * --- entering DataSource::readLCR() --- *
06:59:20.972 (2759195618) * --- entering DataSource::readLCR() --- *
06:59:20.995 (2759194680) * --- entering DataSource::readLCR() --- *
06:59:21.990 (2759196636) * --- entering DataSource::readLCR() --- *
06:59:21.939 (2759195624) * --- entering DataSource::readLCR() --- *
06:59:22.990 (2759197636) * --- entering DataSource::readLCR() --- *
06:59:22.939 (2759196624) * --- entering DataSource::readLCR() --- *
06:59:23.981 (2759198627) * --- entering DataSource::readLCR() --- *
06:59:23.992 (2759197676) * --- entering DataSource::readLCR() --- *
06:59:24.991 (2759199637) * --- entering DataSource::readLCR() --- *
06:59:24.941 (2759198625) * --- entering DataSource::readLCR() --- *
06:59:25.972 (2759200618) * --- entering DataSource::readLCR() --- *
06:59:25.997 (2759199681) * --- entering DataSource::readLCR() --- *
06:59:26.992 (2759201638) * --- entering DataSource::readLCR() --- *
06:59:26.941 (2759200626) * --- entering DataSource::readLCR() --- *
06:59:27.992 (2759202638) * --- entering DataSource::readLCR() --- *
06:59:27.941 (2759201626) * --- entering DataSource::readLCR() --- *
06:59:28.982 (2759203628) * --- entering DataSource::readLCR() --- *
06:59:28.994 (2759202678) * --- entering DataSource::readLCR() --- *
06:59:29.993 (2759204639) * --- entering DataSource::readLCR() --- *
06:59:29.942 (2759203626) * --- entering DataSource::readLCR() --- *
06:59:30.973 (2759205619) * --- entering DataSource::readLCR() --- *
06:59:30.998 (2759204683) * --- entering DataSource::readLCR() --- *
06:59:31.994 (2759206640) * --- entering DataSource::readLCR() --- *
06:59:31.943 (2759205627) * --- entering DataSource::readLCR() --- *
06:59:32.994 (2759207640) * --- entering DataSource::readLCR() --- *
06:59:32.943 (2759206627) * --- entering DataSource::readLCR() --- *
06:59:33.994 (2759208640) * --- entering DataSource::readLCR() --- *
06:59:33.999 (2759207683) * --- entering DataSource::readLCR() --- *
06:59:34.995 (2759209641) * --- entering DataSource::readLCR() --- *
06:59:34.943 (2759208627) * --- entering DataSource::readLCR() --- *
06:59:35.973 (2759210619) * --- entering DataSource::readLCR() --- *
06:59:35.999 (2759209684) * --- entering DataSource::readLCR() --- *
06:59:36.996 (2759211642) * --- entering DataSource::readLCR() --- *
06:59:36.949 (2759210633) * --- entering DataSource::readLCR() --- *

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:37

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:37

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:37

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:37
06:59:37.996 (2759212642) * --- entering DataSource::readLCR() --- *
06:59:37.944 (2759211629) * --- entering DataSource::readLCR() --- *
06:59:38.985 (2759213631) * --- entering DataSource::readLCR() --- *

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:38

SUMMARY STATISTICS

General statistics:
0.00% Checking messages (includes checkpointing)
0.00% Checking periodic tasks
0.00% Waiting for more data
0.00% Converting ASCII data to internal
0.00% Reading input records
0.00% Writing output records in function replicate_io.
0.00% Mapping columns
0.00% Outputting data records
0.00% Performing SQL statements
0.00% Executing BATCHSQL statements
0.00% Executing SQL statements
0.00% Preparing SQL statements
0.00% Commit operations
0.00% Rollback operations
0.00% Checkpointing

Closing Trace File at 2023-05-14 Sun UTC 06:59:39

Viewing Default Log

OCI GG web console has a facility to view the default log file. This is handy for initial troubleshooting. It also provides facility to filter log based on DATE, SEVERITY and Message. These can be combined to drill down for specific message.

Viewing OGG log messages using web console

However, this is no control on log retention or viewing historical data. This limits our option on what messages are available. In a busy system, log data can quickly wrap around.

Hope this was helpful. Do you have any other debugging tips and tricks? See any errors or typos. Leave a comment and share your feedback.

Star or bookmark the repo for latest updates on my scripts.

Reference — adminclient DEBUG ON output

OGG (https://abcddeployment....com OCIGGTestDeployment) 14> SET DEBUG ON
Command 14 succeeded: 'SET DEBUG ON'

OGG (https://abcddeployment....com OCIGGTestDeployment) 15> STATS REPLICAT RNOPK
--------------------------------------------------------------------------------
> GET /services/v2/replicats?threads=all
< Status 200
{
"$schema": "api:standardResponse",
"links": [
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "self",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "describedby",
"href": "https://abcddeployment....com/services/adminsrvr/v2/metadata-catalog/replicats",
"mediaType": "application/schema+json"
}
],
"messages": [],
"response": {
"$schema": "ogg:collection",
"items": [
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RHCPK",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RHCPK"
},
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RNOPK"
},
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RTZAD",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RTZAD"
}
]
}
}
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
> GET /services/v2/replicats?threads=all
< Status 200
{
"$schema": "api:standardResponse",
"links": [
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "self",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "describedby",
"href": "https://abcddeployment....com/services/adminsrvr/v2/metadata-catalog/replicats",
"mediaType": "application/schema+json"
}
],
"messages": [],
"response": {
"$schema": "ogg:collection",
"items": [
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RHCPK",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RHCPK"
},
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RNOPK"
},
{
"links": [
{
"rel": "parent",
"href": "https://abcddeployment....com/services/v2/replicats",
"mediaType": "application/json"
},
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RTZAD",
"mediaType": "application/json"
}
],
"$schema": "ogg:collectionItem",
"name": "RTZAD"
}
]
}
}
--------------------------------------------------------------------------------

Sending STATS request to Replicat group RNOPK ...

--------------------------------------------------------------------------------
> POST /services/v2/replicats/RNOPK/command
{
"command": "STATS",
"isReported": true
}
----------------------------------------
< Status 200
{
"$schema": "api:standardResponse",
"links": [
{
"rel": "canonical",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK/command",
"mediaType": "application/json"
},
{
"rel": "self",
"href": "https://abcddeployment....com/services/v2/replicats/RNOPK/command",
"mediaType": "application/json"
}
],
"messages": [],
"response": {
"$schema": "er:commandResult",
"reply": "OKNODOT\t\nParallel Replicat statistics:\n\n\n*** Total statistics since 2023-04-12 08:32:48 ***\n No transactions yet processed.\n\n*** Daily statistics since 2023-05-13 00:00:00 ***\n No transactions yet processed.\n\n*** Hourly statistics since 2023-05-13 18:00:00 ***\n No transactions yet processed.\n\n*** Latest statistics since 2023-04-12 08:32:48 ***\n No transactions yet processed.\n\nStart of statistics at 2023-05-13 18:00:30.\n\nEnd of statistics.",
"replyData": {
"$schema": "ogg:stats",
"stats": [
{
"parallelReplicat": true,
"since": "2023-04-12T08:32:48.237Z",
"operations": [
{
"operation": "transactions",
"count": 0
}
]
},
{
"parallelReplicat": true,
"since": "2023-05-13T00:00:00.000Z",
"operations": [
{
"operation": "transactions",
"count": 0
}
]
},
{
"parallelReplicat": true,
"since": "2023-05-13T18:00:00.000Z",
"operations": [
{
"operation": "transactions",
"count": 0
}
]
},
{
"parallelReplicat": true,
"since": "2023-04-12T08:32:48.237Z",
"operations": [
{
"operation": "transactions",
"count": 0
}
]
}
]
}
}
}
--------------------------------------------------------------------------------

Parallel Replicat statistics:

*** Total statistics since 2023-04-12 08:32:48 ***
No transactions yet processed.

*** Daily statistics since 2023-05-13 00:00:00 ***
No transactions yet processed.

*** Hourly statistics since 2023-05-13 18:00:00 ***
No transactions yet processed.

*** Latest statistics since 2023-04-12 08:32:48 ***
No transactions yet processed.

Start of statistics at 2023-05-13 18:00:30.

End of statistics.
Command 15 succeeded: 'STATS REPLICAT RNOPK'

--

--

Data Voyage by Jigar Doshi
Oracle Developers

Master Principal Cloud Architect @ Oracle Singapore. Data enthusiast. Sharing my adventures in world of data