HIVE-29753: Add configurable WARN logging for slow getFileInfo calls in StorageBasedAuthorizationProvider

[Indhumathi27]

What changes were proposed in this pull request?

This PR adds configurable WARN-level logging for slow getFileInfo calls performed during storage-based authorization checks.

A new configuration property,
hive.metastore.authorization.fileinfo.slow.warn.threshold.ms (default: 300 ms, -1 to disable), is introduced to control when a WARN log should be emitted.

StorageBasedAuthorizationProvider.checkPermissions() is instrumented to measure the time spent in FileUtils.getFileStatusOrNull() for both:

• the initial path lookup, and
• parent directory traversal when the target path does not exist.

If the elapsed time exceeds the configured threshold, a WARN log containing the path and elapsed time is emitted.

Integration tests have also been added to verify:

• no WARN is emitted when the feature is disabled (threshold = -1), and
• a WARN is emitted when the configured threshold is exceeded using a slow FileSystem implementation.

Why are the changes needed?

Storage-based authorization relies on filesystem metadata lookups (getFileInfo), which may become slow due to NameNode latency or filesystem performance issues. These delays are currently not visible in normal logs, making them difficult to diagnose without enabling verbose logging or profiling.

This change provides lightweight observability by logging only operations whose latency exceeds a configurable threshold, helping administrators identify slow filesystem operations while avoiding excessive log noise.

Does this PR introduce any user-facing change?
Yes.

A new configuration property has been added:
hive.metastore.authorization.fileinfo.slow.warn.threshold.ms

• Default: 300
• Value -1: disables WARN logging.

When enabled, slow filesystem metadata lookups performed during storage-based authorization checks will generate WARN log entries if they exceed the configured threshold.
No functional behavior of authorization is changed.

How was this patch tested?
Added integration tests covering both positive and negative scenarios

[sonarqubecloud]

Quality Gate passed

Issues
7 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.3% Duplication on New Code

See analysis details on SonarQube Cloud

[ayushtkn]

I think this is something DFSClient should be worried about not Hive as a client, Why not use the Hadoop configs?

<property>
    <name>ipc.server.log.slow.rpc</name>
    <value>false</value>
    <description>This setting is useful to troubleshoot performance issues for
     various services. If this value is set to true then we log requests that
     fall into 99th percentile as well as increment RpcSlowCalls counter.
    </description>
</property>

<property>
  <name>ipc.server.log.slow.rpc.threshold.ms</name>
  <value>0</value>
  <description>The threshold in milliseconds for logging slow rpc when ipc.server.log.slow.rpc is enabled.
    Besides of being much slower than other RPC requests, an RPC request has to take at least the threshold value
    defined by this property before it can be considered as slow. By default, this threshold is set to 0 (disabled).
  </description>
</property>

[Indhumathi27]

@ayushtkn Thanks for the review. I agree ipc.server.log.slow.rpc is the right way at the IPC layer, but I would like to highlight the advantages of having this in Hive as well.

Client-side visibility without NameNode access
ipc.server.log.slow.rpc requires NameNode config changes and a restart. Hive/HMS operators in most enterprise environments control only the HMS process — they cannot touch NameNode configs. This fix gives them actionable signal without any dependency on the infrastructure team.

Operation context
The NameNode sees an anonymous getFileInfo RPC. It has no idea why it was called. The Hive-side log tells you exactly which operation triggered it:

• WARN StorageBasedAuthorizationProvider - Slow getFileInfo during
• storage-based authorization check: path=hdfs://nn/warehouse/mydb, elapsed=4523ms

Without this, even with ipc.server.log.slow.rpc enabled on the NameNode, you still cannot correlate the slow RPC to a specific HMS operation (auth check vs table scan vs partition listing).

Path information for diagnosis
The Hive-side log includes the HDFS path being authorized. This is critical for diagnosis — it tells operators whether the slow call is on a warehouse root, a specific database, or a partition path, helping narrow down the issue to a specific table or misconfigured location.

Lower blast radius restart
Both require a process restart to change the config. However, restarting the NameNode affects the entire HDFS cluster and all clients — it is a high-impact operation that typically requires a change request and scheduled maintenance window. Restarting HMS affects only Hive metadata operations and is a routine, low-impact operation that the Hive team can do independently without involving the infrastructure team or affecting other HDFS workloads.

Threshold tuning per deployment
Different deployments have different NN latency baselines. A threshold of 1s may be normal for one cluster and a warning sign for another. Having the config on the Hive side lets operators tune it to their environment independently.

Filesystem agnostic — works for any future FileSystem
ipc.server.log.slow.rpc is specific to Hadoop IPC and only covers HDFS NameNode RPC calls. With storage backends like S3, Azure ADLS, GCS, or Vast S3 becoming increasingly common in Hive deployments, slow getFileInfo calls can occur on any FileSystem implementation — not just HDFS. Since this fix instruments FileUtils.getFileStatusOrNull() at the Hive level, it will automatically provide slow-call visibility for any FileSystem that storage-based authorization runs against today or in the future, without requiring any equivalent mechanism to exist in those storage systems.

Both mechanisms complement each other — ipc.server.log.slow.rpc gives NameNode-level visibility, while this fix gives HMS-level visibility with operation context.

[ayushtkn]

ipc.server.log.slow.rpc requires NameNode config changes and a restart.

If my memory treats me well, that is reconfigurable and doesn't require a Restart, Hadoop has set of reconfigurable properties, which can be reconfigured without restarting the server
https://github.com/apache/hadoop/blob/767c9da6f34f9ed57311ba9f43497563c05b9f46/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/NameNode.java#L2539-L2560

I do understand your use case, But I feel this is something to be dealt at the Hadoop RPC Client layer rather than the Hive as a FS Client doing this magic.

If we want to implement it in Hive, which I seriously think we shouldn't, we should not just for getFileInfo or so. It should be a wrapper FS, which tracks the time of each call and delegates to the underlying FS.

-> start counter -> call any HCFS API-> stop counter -> log accordingly. This you can just hinge via fs.*.impl configs.

Logging one API in one interface looks overkill to me. I won't block you if others are fine with it, but it won't help you much either IMO, getFileInfo might get pass at SBA, maybe some other write call is chocking, the write logic requires a write lock + writing to JN's that maybe slow, so I don't think it will help you in long run, or if the cluster isn't using SBA