[HADOOP-10274] Lower the logging level from ERROR to WARN for UGI.doAs method

• Type: Improvement
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 1.0.4
• Fix Version/s: 2.3.0
• Component/s: security

Environment

hadoop-1.0.4, hbase-0.94.16, krb5-server-1.6.1-31.el5_3.3, CentOS release 5.3 (Final)

• Hadoop Flags: Reviewed
• Assignee: takeshi.miao
• Reporter: takeshi.miao
• Created: 24/Jan/14 02:54
• Updated: 03/Sep/14 23:33
• Resolved: 28/Jan/14 05:03

Description

Recently we got the error msg "Request is a replay (34) - PROCESS_TGS" while we are using the HBase client API to put data into HBase-0.94.16 with krb5-1.6.1 enabled. The related msg as follows...

[2014-01-15 09:40:38,452][hbase-tablepool-1-thread-3][ERROR][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1124)): PriviledgedActionException as:takeshi_miao@LAB cause:javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Request is a replay (34) - PROCESS_TGS)]
[2014-01-15 09:40:38,453][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation.logPriviledgedAction(UserGroupInformation.java:1143)): PriviledgedAction as:takeshi_miao@LAB from:sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                                                                                          
[2014-01-15 09:40:38,453][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.ipc.SecureClient](org.apache.hadoop.hbase.ipc.SecureClient$SecureConnection$1.run(SecureClient.java:213)): Exception encountered while connecting to the server : javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Request is a replay (34) - PROCESS_TGS)]
[2014-01-15 09:40:38,454][hbase-tablepool-1-thread-3][INFO ][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation.reloginFromTicketCache(UserGroupInformation.java:657)): Initiating logout for takeshi_miao@LAB
[2014-01-15 09:40:38,454][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation$HadoopLoginModule.logout(UserGroupInformation.java:154)): hadoop logout
[2014-01-15 09:40:38,454][hbase-tablepool-1-thread-3][INFO ][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation.reloginFromTicketCache(UserGroupInformation.java:667)): Initiating re-login for takeshi_miao@LAB
[2014-01-15 09:40:38,455][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation$HadoopLoginModule.login(UserGroupInformation.java:146)): hadoop login
[2014-01-15 09:40:38,456][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation$HadoopLoginModule.commit(UserGroupInformation.java:95)): hadoop login commit
[2014-01-15 09:40:38,456][hbase-tablepool-1-thread-3][DEBUG][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation$HadoopLoginModule.commit(UserGroupInformation.java:100)): using existing subject:[takeshi_miao@LAB, UnixPrincipal: takeshi_miao, UnixNumericUserPrincipal: 501, UnixNumericGroupPrincipal [Primary Group]: 501, UnixNumericGroupPrincipal [Supplementary Group]: 502, takeshi_miao@LAB]

Finally, we found that the HBase would doing the retry (5 * 10 times) and recovery this 'request is a replay (34)' issue, but based on the HBase user viewpoint, the error msg at first line may be frightful, as we were afraid there was any data loss occurring at the first sight...

[2014-01-15 09:40:38,452][hbase-tablepool-1-thread-3][ERROR][org.apache.hadoop.security.UserGroupInformation](org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1124)): PriviledgedActionException as:takeshi_miao@LAB cause:javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Request is a replay (34) - PROCESS_TGS)]

So I'd like to suggest to change the logging level from 'ERROR' to 'WARN' for o.a.hadoop.security.UserGroupInformation#doAs(PrivilegedExceptionAction<T>) method

  public <T> T doAs(PrivilegedExceptionAction<T> action
                    ) throws IOException, InterruptedException {
    try {
      // ...
    } catch (PrivilegedActionException pae) {
      Throwable cause = pae.getCause();
      LOG.error("PriviledgedActionException as:"+this+" cause:"+cause); // I mean here
      // ...
    }
  }

Due to this method already throws _checked exception_s which can be handled by the client code, so the error may not really be an error if client code can handle it...such as this case.

For more details pls refer to HBASE-10379

Issue Links

• duplicates: HADOOP-10015 UserGroupInformation prints out excessive ERROR warnings
• is related to: HADOOP-10015 UserGroupInformation prints out excessive ERROR warnings
• is related to: HBASE-10379 Lower the msg "Request is a replay (34) - PROCESS_TGS" from logging level ERROR to WARN