[jira] [Commented] (HDDS-16383) Ozone client logs full stack trace at INFO on every OM leader failover (RetryInvocationHandler)

["Mahesh kumar gaddam (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/HDDS-16383?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18111748#comment-18111748 ] 

Mahesh kumar gaddam commented on HDDS-16383:
--------------------------------------------

Had a look at this on master, and the cause turned out to be a bit different than it appears.

First, clients aren't hitting a random OM. OMFailoverProxyProviderBase starts both proxy indices at 0, so everyone deterministically tries the first OM in ozone.om.nodes. If that's not the leader, every fresh client pays one redirect.

The bigger surprise is that the client isn't printing the stack trace at all. The forked handler in io_/retry/RetryInvocationHandler calls LOG.info(b.toString()) and never passes the exception to the logger. The frames are inside the message: it stringifies a RemoteException whose text was built on the OM side by StringUtils.stringifyException() in ipc_/Server.java (~874, ~900). So those OzoneManagerRatisServer frames are the OM's own stack, shipped over the wire. Which means the obvious fix, not passing the exception to the logger, does nothing.

Simplest fix I can see is to make OMNotLeaderException stackless by overriding fillInStackTrace() to return this. No frames captured, so stringifyException gives a clean one-liner, and it fixes every client regardless of log4j config. It's control flow rather than a fault, so I think that's a fair thing to do. Only five construction sites, all in OzoneManagerRatisServer and OMRangerBGSyncService.

 
{code:java}
@Override
public synchronized Throwable fillInStackTrace() {
  return this;
} {code}
Downside is we'd lose the server-side throw site in logs. Doesn't worry me much since the message already names the current peer and suggested leader, but happy to be told otherwise.

Alternative would be a terse-message special case in the handler, though that only helps the Java client. Does the stackless route sound OK? Can put up a patch.

[~lpigueiras]  [@szetszwo|https://github.com/szetszwo] [@yandrey321|https://github.com/yandrey321] [~weichiu]  

> Ozone client logs full stack trace at INFO on every OM leader failover (RetryInvocationHandler)
> -----------------------------------------------------------------------------------------------
>
>                 Key: HDDS-16383
>                 URL: https://issues.apache.org/jira/browse/HDDS-16383
>             Project: Apache Ozone
>          Issue Type: Improvement
>          Components: Ozone Client
>    Affects Versions: 2.2.0
>            Reporter: Luis Pigueiras
>            Priority: Minor
>
> h3. Summary
> When accessing Ozone via hdfs commands (like {{hdfs dfs -ls ofs://...}}, every freshly-created client starts by contacting a random OM rather than a cached/known leader. With N configured OMs in HA, this means there is only a 1-in-N chance of hitting the actual leader on the first try, the other (N-1)/N of the time, the client gets redirected via an {{OMNotLeaderException}}, which is logged at INFO with a full exception and stack trace.
> As far as I understand, this logging retrial mechanism is normal with a OM HA setup, so having it as a full INFO-level stack trace overstates its severity and adds noise to normal client commands.
> h3. Steps to reproduce
> # Repeat any {{hdfs dfs}} / {{ofs://}} command against a cluster:
> {code}
> hdfs dfs -ls ofs://<cluster>/<existingpath>/
> {code}
> # Eventually you will get some message like
> {code}
> INFO retry.RetryInvocationHandler: org.apache...ServiceException:
> org.apache.hadoop.ipc_.RemoteException(...OMNotLeaderException):
> OM:<om-host> is not the leader. Suggested leader is OM:<om-host2>
>     at org.apache.hadoop.ozone.om.ratis.OzoneManagerRatisServer...
>     ... (full stack trace)
> {code}
> h3. Expected behavior
> This should probably not be logged as a full INFO-level stack trace? Maybe DEBUG level, or a terse single-line INFO message without the stack trace, would be more appropriate, this is an expected, transparently-handled event, not an error condition. Right now we have modified the log4j.properties to add this to reduce the noise from client commands.
> {code}
> log4j.logger.org.apache.hadoop.io_.retry.RetryInvocationHandler=WARN
> {code}



--
This message was sent by Atlassian Jira
(v8.20.10#820010)

---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscribe@ozone.apache.org
For additional commands, e-mail: issues-help@ozone.apache.org