[HIVE-25970] Missing messages in HS2 operation logs

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 4.0.0-alpha-1
• Component/s: HiveServer2
• Labels: pull-request-available
• Target Version/s: 4.0.0
• Assignee: Stamatis Zampetakis
• Reporter: Stamatis Zampetakis
• Created: 22/Feb/22 17:31
• Updated: 17/Nov/22 08:48
• Resolved: 25/Feb/22 17:31

Description

After HIVE-22753 & HIVE-24590, with some unlucky timing of events, operation log messages can get lost and never appear in the appropriate files.

The changes in HIVE-22753 will prevent a HushableRandomAccessFileAppender from being created if the latter refers to a file that has been closed in the last second. Preventing the creation of the appender also means that the message which triggered the creation will be lost forever. In fact any message (for the same query) that comes in the interval of 1 second will be lost forever.

Before HIVE-24590 the appender/file was closed only once (explicitly by HS2) and thus the problem may be very hard to notice in practice. However, with the arrival of HIVE-24590 appenders may close much more frequently (and not via HS2) making the issue reproducible rather easily. It suffices to set hive.server2.operation.log.purgePolicy.timeToLive property very low and check the operation logs.

The problem was discovered by investigating some intermittent failures in operation logging tests (e.g., TestOperationLoggingAPIWithTez).

Issue Links

• is caused by: HIVE-24590 Operation Logging still leaks the log4j Appenders
• is caused by: HIVE-22753 Fix gradual mem leak: Operationlog related appenders should be cleared up on errors
• links to: GitHub Pull Request #3048