Enhanced filtering for the JDBC logger in the Enforce Server
search cancel

Enhanced filtering for the JDBC logger in the Enforce Server

book

Article ID: 165002

calendar_today

Updated On: 06-19-2023

Products

Data Loss Prevention Enforce Data Loss Prevention

Issue/Introduction

An enhanced filtered logging capability is available for the JDBC logger in the Symantec Data Loss Prevention Enforce Server.  This new capability enables you to filter out queries that execute quickly and only log those queries that take longer to process.  This may reveal Oracle database-related delays.

You can also limit logging to Oracle execution plan information for the queries whose execution time exceeds a certain configurable threshold. This can be used to obtain critical information about how Oracle executed the query.  You can see the complete execution plan with optimizer-based decisions. You can also see the breakdown of individual steps with their respective execution times, memory buffers, and disk input and output access.

Resolution

For DLP 15.8 MP3 and 16.0, here is the latest information about the JDBC logger:

JDBCLogger V4.3 improved configuration, logging of configuration information and guidance:
=========================================================================================

Note: the JDBCLogHandler.level configuration does not matter anymore. Default configuration out of the box is:
# Switch to FINE to enable JDBC logging
com.vontu.util.jdbc.JDBCLogHandler.level = INFO
The JDBCLogger 4.3 automatically syncs up the JDBCLogHandler.level to the com.vontu.jdbc.level at runtime, preventing configuration mistakes. Hence you don't have to change the line above anymore, everything will work based on com.vontu.jdbc.level

CONFIGURATION:
=============

The JDBC logger related entries in <Service>Logging.properties for Manager, MC and IP have been streamlined / improved to ease the configuration:

# Controls logging of Database operations performed via JDBC
com.vontu.util.jdbc.JDBCLogHandler.pattern = $VONTU_LOG_PATH$/debug/IncidentPersister_jdbc_%g.log
com.vontu.util.jdbc.JDBCLogHandler.limit = 5000000
com.vontu.util.jdbc.JDBCLogHandler.count = 5
# Switch to FINE to enable JDBC logging             <= REMOVED this comment
com.vontu.util.jdbc.JDBCLogHandler.level = INFO     <= REMOVED, the JDBCLogHandler is now auto-configured
com.vontu.util.jdbc.JDBCLogHandler.append = true
com.vontu.util.jdbc.JDBCLogHandler.formatter = com.vontu.logging.NonLocalizingSimpleFormatter     <= REMOVED, the formatter is actually hard-coded and not configurable
com.vontu.util.jdbc.JDBCLogHandler.encoding = UTF-8


# JDBC Logger level: INFO = high-level statistics and errors only, switch to FINE to enable JDBC query logging, FINER for more verbose logging.
com.vontu.jdbc.level = INFO
# Log JDBC queries whose execution time (in milliseconds) meets the threshold. 0 = log all queries irrespective of execution time.
com.vontu.jdbc.threshold_ms = 500
# Capture Oracle execution plans for all JDBC queries and log when execution time (in milliseconds) meets the plan threshold. Min value >= threshold_ms and >= 500. 0 = do not capture.
com.vontu.jdbc.query_plan_threshold_ms = 0            <= DEFAULT VALUE CHANGED FROM 500 TO 0, TO DISABLE THIS COSTLY FEATURE BY DEFAULT
# Caller name filtering inclusion CSV list, only JDBC queries whose caller name contains at least one of the token(s) will be retained for logging. Empty list = no inclusion filtering.
com.vontu.jdbc.include = 
# Caller name filtering exclusion CSV list, only JDBC queries whose caller name does NOT contain any of the token(s) will be retained for logging. Empty list = no exclusion filtering.
com.vontu.jdbc.exclude = 


JDBC LOG MESSAGES AT STARTUP OR WHEN CONFIGURATION IS CHANGED:
=============================================================

A. When the logger is configured at INFO level (default out of the box), two INFO lines summarize the running context:

-- 2022/01/04 10:16:42.693 INFO thread=26, com.vontu.jdbc.level=INFO. The JDBC logger 4.3 beta 2 is active, callers statistics reporting will be logged every 5 minutes. SecurityManager optimization: enabled
-- 2022/01/04 10:16:42.693 INFO thread=26, com.vontu.jdbc.level=INFO. JDBC query logging is disabled, no SQL query will be logged. Set level to FINE to enable JDBC query logging. Set level to FINER for more verbose logging.

B. If the logger has been somehow configured at WARNING, SEVERE or even turned OFF, a WARNING is issued with info and guidance:

-- 2022/01/04 10:19:42.731 WARNING thread=26, com.vontu.jdbc.level=WARNING. The JDBC logger 4.3 beta 2 is inactive. Set level to INFO or below (FINE to log SQL queries) in <ServiceName>Logging.properties to activate the JDBC logger.
-- 2022/01/04 10:20:32.717 WARNING thread=26, com.vontu.jdbc.level=SEVERE. The JDBC logger 4.3 beta 2 is inactive. Set level to INFO or below (FINE to log SQL queries) in <ServiceName>Logging.properties to activate the JDBC logger.
-- 2022/01/04 10:21:02.735 WARNING thread=26, com.vontu.jdbc.level=OFF. The JDBC logger 4.3 beta 2 is inactive. Set level to INFO or below (FINE to log SQL queries) in <ServiceName>Logging.properties to activate the JDBC logger.

C. If the logger has been somehow configured at an invalid level, it will be auto-corrected to INFO:

-- 2022/01/04 10:22:27.740 WARNING thread=26, com.vontu.jdbc.level incorrect value: FOOBAR, level will be set to INFO
-- 2022/01/04 10:22:27.740 INFO thread=26, com.vontu.jdbc.level=INFO. The JDBC logger 4.3 beta 2 is active, callers statistics reporting will be logged every 5 minutes. SecurityManager optimization: enabled
-- 2022/01/04 10:22:27.740 INFO thread=26, com.vontu.jdbc.level=INFO. JDBC query logging is disabled, no SQL query will be logged. Set level to FINE to enable JDBC query logging. Set level to FINER for more verbose logging.

D. If the logger is configured at FINE or above (FINER, FINEST), modified and additional INFO lines provide query logging information, security warning and guidance, and filtering info (default config values shown below):

-- 2022/01/04 10:00:01.848 INFO thread=26, com.vontu.jdbc.level=FINER. The JDBC logger 4.3 beta 2 is active, callers statistics reporting will be logged every 5 minutes. SecurityManager optimization: enabled
-- 2022/01/04 10:00:01.848 INFO thread=26, com.vontu.jdbc.level=FINER. JDBC query logging is enabled, WARNING: this may reveal sensitive information exchanged between the application and the database. Set level to INFO to disable query logging, or use filtering to limit the scope.
-- 2022/01/04 10:00:01.848 INFO thread=26, Caller name filtering is inactive, SQL queries will be logged irrespective of their originating caller. Configure com.vontu.jdbc.include and/or com.vontu.jdbc.exclude properties with a comma separated list of tokens to enable caller name filtering.
-- 2022/01/04 10:00:01.848 INFO thread=26, com.vontu.jdbc.threshold_ms=500 ms. Execution time filtering is active, only SQL queries executing in 500 millisecond(s) or higher will be logged. Set the value to 0 to log all queries irrespective of execution time.
-- 2022/01/04 10:00:01.848 INFO thread=26, com.vontu.jdbc.query_plan_threshold_ms=2000 ms. Oracle query execution plan logging is active. Only logged queries executing in 2000 milliseconds or higher will also have their Oracle execution plan logged. Set the value to 0 to turn off the feature.
-- 2022/01/04 10:00:01.848 WARNING thread=26, Oracle query execution plan logging is a performance impacting feature affecting all queries when enabled. Activate it only when troubleshooting Oracle performance issues. Consider using a high value threshold and/or name filtering to slightly limit the scope and performance impact of writing the plan to logs.

D.1. Use case when name filtering is active/configured (com.vontu.jdbc.include and/or com.vontu.jdbc.exclude is/are configured with either one having at least one token defined, which activates name filtering):

-- 2022/01/04 10:05:12.574 INFO thread=26, Caller name filtering is active, only SQL queries whose caller is passing the inclusion and exclusion lists below (in that order) will be logged:

D.1a. Both include and exclude are active:

-- 2022/01/04 10:05:12.574 INFO thread=26, com.vontu.jdbc.include=#org.quartz, com.vontu, com.symantec.dlp. (Only queries whose caller name contains at least one of the token(s) will be retained for logging)
-- 2022/01/04 10:05:12.574 INFO thread=26, com.vontu.jdbc.exclude=DatabaseStateChecker.databaseAvailable, UserLockoutEventHandler (Only queries whose caller name does NOT contain any of the token(s) will be retained for logging)

D.1b. Only exclude is active:

-- 2022/01/04 10:06:12.586 INFO thread=26, com.vontu.jdbc.include= (No inclusion defined, all queries are valid for logging irrespective of their caller name)
-- 2022/01/04 10:06:12.586 INFO thread=26, com.vontu.jdbc.exclude=DatabaseStateChecker.databaseAvailable, UserLockoutEventHandler (Only queries whose caller name does NOT contain any of the token(s) will be retained for logging)

D.1c. Only include is active:

-- 2022/01/04 10:07:02.599 INFO thread=26, com.vontu.jdbc.include=#org.quartz, com.vontu, com.symantec.dlp. (Only queries whose caller name contains at least one of the token(s) will be retained for logging)
-- 2022/01/04 10:07:02.599 INFO thread=26, com.vontu.jdbc.exclude= (No exclusion defined, no query will be further excluded by its caller name)

D.2. When no execution time filtering is configured:

-- 2022/01/04 10:14:52.679 INFO thread=26, com.vontu.jdbc.threshold_ms=0 ms. Execution time filtering is inactive, SQL queries will be logged irrespective of their execution time. Set a value > 0 to filter out the faster executing queries.

D.3. When no Oracle execution plan logging is configured:

-- 2022/01/04 10:14:27.676 INFO thread=26, com.vontu.jdbc.query_plan_threshold_ms=0 ms. Oracle query execution plan logging is inactive. Set value to 500 ms or higher to log Oracle execution plans for slow executing queries.

D.4. When Oracle plan logging threshold is misconfigured (below threshold_ms), auto-correcting:

-- 2022/01/04 10:47:53.478 WARNING thread=26, com.vontu.jdbc.query_plan_threshold_ms incorrect value: 700 ms. Minimum value: 1000 ms. Default value (2000 ms) will be used

-- 2022/01/04 10:49:33.492 WARNING thread=26, com.vontu.jdbc.query_plan_threshold_ms incorrect value: 700 ms. Minimum value: 5000 ms. Default value (5000 ms) will be used

E. A summary of the current configuration is now logged after each Callers report (every 5 minutes), to help Support engineers / log reviewers understand what the configuration is even if logs have rolled over since the last
change to the configuration was made (first line below, the next 3 lines with detailed processing statistics have not changed except for the additional display of the lazy loading count breakdown on the 'JdbcLogger Statistics' line
that shows how many OJB 1:1, 1:N and Hibernate 1:1, 1:N lazy loading have been detected):

-- 2022/01/11 11:22:50.262 INFO thread=25, JdbcLogger 4.3 beta 3, Filtering: level=FINEST thresholdMs=500 queryPlanThresholdMs=700 include=#org.quartz,com.vontu,com.symantec.dlp. exclude=DatabaseStateChecker.databaseAvailable,UserLockoutEventHandler
-- 2022/01/11 11:22:50.262 INFO thread=25, JdbcLogger Statistics: connections: 12874, queries: 22823 (filtered out: 22753, 99.69%), log records: 90153, Oracle query plans: 4 (0.018%), Lazy counts: [1913, 2157, 387, 14490]
-- 2022/01/11 11:22:50.262 INFO thread=25, StackRecorder Statistics: count: 22823, constructor: 860 ms (avg: 0.038 ms, th: 62.9%, cc: 37.1%). Frames: 940K (avg: 41), accessed: 23542 (2.50%, avg: 1.03), time: 241 ms (avg: 0.011 ms)
-- 2022/01/11 11:22:50.262 INFO thread=25, JdbcLoggerTask Statistics: runs: 70496, runTime: 70540 sec, processingTime: 2 sec (0.003%)

IMPROVED DATABASE INACTIVE CONNECTIONS TRACKING:
===============================================

New millisecond precision and tracking/display of thread IDs alongside thread names:

-- 2022/02/23 17:50:48.508 INFO thread=25, Database inactive connections (> 5 min) report:
===================================================================================================================================================================================================================================
Opened on               | By Thread ID / name                                | Stmt | Last activity           | By Thread ID / name                                | Last used by
===================================================================================================================================================================================================================================
2022/02/23 16:11:10.074 |        90 / managerScheduler_QuartzSchedulerThread |    1 | 2022/02/23 16:11:10.074 |        90 / managerScheduler_QuartzSchedulerThread | org.quartz.impl.jdbcjobstore.StdJDBCDelegate.selectTriggerToAcquire(2571)
2022/02/23 16:11:33.911 | 109 / QuartzScheduler_managerScheduler-manager_Mis |    1 | 2022/02/23 16:11:33.911 | 109 / QuartzScheduler_managerScheduler-manager_Mis | org.quartz.impl.jdbcjobstore.StdJDBCDelegate.countMisfiredTriggersInState(416)
2022/02/23 16:10:55.045 |                     92 / database-connect-status_1 |    1 | 2022/02/23 16:10:55.045 |                     92 / database-connect-status_1 | com.vontu.enforce.domainlayer.common.database.DatabaseStateChecker.databaseAvailable(54)
===================================================================================================================================================================================================================================

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------

For versions of DLP prior to 15.8 MP3, see the attached document "Enhanced filtering for the JDBC logger in the Enforce Server".
That document was released for 14.6 MP1 and was valid through 15.8 MP2.

Attachments

Enhanced filtering for the JDBC logger in the Enforce Server.pdf get_app
Powered by Wolken Software