Could not find uri with key dfs.encryption.key.provider.uri to create a keyProvider in HDFS

[#1]

CDH Version: CDH5.4.5

Issue: When HDFS Encryption is enabled using KMS available in Hadoop CDH 5.4 , getting error while putting file into encryption zone.

Steps:

Steps for Encryption of Hadoop as follows:

    Creating a key [SUCCESS]

    [tester@master ~]$ hadoop key create 'TDEHDP'
    -provider kms://https@10.1.118.1/key_generator/kms -size 128
    tde group has been successfully created with options
    Options{cipher='AES/CTR/NoPadding', bitLength=128, description='null', attributes=null}.
    KMSClientProvider[https://10.1.118.1/key_generator/kms/v1/] has been updated.

2.Creating a directory [SUCCESS]

[tester@master ~]$ hdfs dfs -mkdir /user/tester/vs_key_testdir

    Adding Encryption Zone [SUCCESS]

    [tester@master ~]$ hdfs crypto -createZone -keyName 'TDEHDP'
    -path /user/tester/vs_key_testdir
    Added encryption zone /user/tester/vs_key_testdir

    Copying File to encryption Zone [ERROR]

    [tdetester@master ~]$ hdfs dfs -copyFromLocal test.txt /user/tester/vs_key_testdir

    15/09/04 06:06:33 ERROR hdfs.KeyProviderCache: Could not find uri with key [dfs.encryption.key.provider.uri] to create a keyProvider !! copyFromLocal: No KeyProvider is configured, cannot access an encrypted file 15/09/04 06:06:33 ERROR hdfs.DFSClient: Failed to close inode 20823 org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException): No lease on /user/tester/vs_key_testdir/test.txt.COPYING (inode 20823): File does not exist. Holder DFSClient_NONMAPREDUCE_1061684229_1 does not have any open files.

Any idea/suggestion will be helpful.

[#2]

Did you ensure to redeploy client configuration, and restart HDFS both, after adding the KMS service and linking HDFS with it? Your client is basically complaining of a missing KMS config, but without trace logs am also unsure if its coming instead out of the NN being unable to talk to KMS, or just purely the client.

[#3]

Hi,

This looks like the bug: https://issues.apache.org/jira/browse/HDFS-7931, fixed only in hdfs 2.7.1 while CDH5.5.1 still uses hdfs 2.6.0.

A log snapshot is below:

Feb 15, 11:37:41.636 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 add_partition : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:41.717 PM INFO org.apache.hadoop.hive.common.FileUtils
Creating directory if it doesn't exist: hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6/cm_test_table/p1=p0/p2=420
Feb 15, 11:37:42.508 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 add_partition : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:42.509 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 add_partition : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:42.588 PM INFO org.apache.hadoop.hive.common.FileUtils
Creating directory if it doesn't exist: hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6/cm_test_table/p1=p1/p2=421
Feb 15, 11:37:44.537 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 get_table : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:44.551 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 get_table : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:46.384 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 drop_table : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE
Feb 15, 11:37:46.385 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 drop_table : db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 tbl=CM_TEST_TABLE

Feb 15, 11:37:46.420 PM ERROR org.apache.hadoop.hdfs.KeyProviderCache
Could not find uri with key [dfs.encryption.key.provider.uri] to create a keyProvider !!

Feb 15, 11:37:46.602 PM INFO hive.metastore.hivemetastoressimpl
deleting hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6/cm_test_table
Feb 15, 11:37:46.609 PM INFO org.apache.hadoop.fs.TrashPolicyDefault
Namenode trash configuration: Deletion interval = 1440 minutes, Emptier interval = 0 minutes.
Feb 15, 11:37:46.657 PM INFO hive.metastore.hivemetastoressimpl
Moved to trash: hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6/cm_test_table
Feb 15, 11:37:46.770 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 get_database: cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.778 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 get_database: cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.805 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 drop_database: cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.806 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 drop_database: cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.831 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 get_all_tables: db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.831 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 get_all_tables: db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.851 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: source:172.17.0.2 get_functions: db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 pat=*
Feb 15, 11:37:46.852 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=source:172.17.0.2 get_functions: db=cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 pat=*
Feb 15, 11:37:46.876 PM INFO org.apache.hadoop.hive.metastore.ObjectStore
Dropping database cloudera_manager_metastore_canary_test_db_hive_hivemetastore_51059e403b58f7a4f83fffcc4add47c6 along with all tables
Feb 15, 11:37:46.922 PM INFO hive.metastore.hivemetastoressimpl
deleting hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:46.946 PM INFO org.apache.hadoop.fs.TrashPolicyDefault
Namenode trash configuration: Deletion interval = 1440 minutes, Emptier interval = 0 minutes.
Feb 15, 11:37:47.018 PM INFO hive.metastore.hivemetastoressimpl
Moved to trash: hdfs://cdh-docker:8020/user/hue/.cloudera_manager_hive_metastore_canary/hive_HIVEMETASTORE_51059e403b58f7a4f83fffcc4add47c6
Feb 15, 11:37:50.429 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: Shutting down the object store...
Feb 15, 11:37:50.430 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=Shutting down the object store...
Feb 15, 11:37:50.431 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
19: Metastore shutdown complete.
Feb 15, 11:37:50.431 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore.audit
ugi=hue ip=172.17.0.2 cmd=Metastore shutdown complete.
Feb 15, 11:39:42.372 PM INFO org.apache.hadoop.hive.metastore.HiveMetaStore
Shutting down hive metastore.

[#4]

CDH's base release versions are just that: base. The fix for the harmless
log print due to HDFS-7931 is present in all CDH5 releases since CDH 5.4.1.

If you see that error in context of having configured a KMS, then its a
worthy one to consider. If you do not use KMS or EZs, then the error may be
ignored. Alternatively upgrade to the latest CDH5 (5.4.x or 5.5.x) releases
to receive a bug fix that makes the error only appear when in the context
of a KMS being configured over an encrypted path.

Per your log snippet, I don't see a problem (the canary does not appear to
be failing?). If you're trying to report a failure, please send us more
characteristics of the failure, as HDFS-7931 is a minor issue with an
unnecessary log print.

[#5]

Harsh,

You make a fair point. I will add more information you requested for you and for the benefit of others who would hit on this thread.

First of all: this is not an issue as you have quite rightly have said.

My scenario:

We plan to upgrade CDH from 5.4.X to 5.5.<LATEST>. So we did want to dry run in a docker to see any sticking issues. This is one of the issues that stands out. The upgrade did fail in the first time initialization towards the end. 

I just logged into CM home page and did start services manually - which seemed to work fine for all the processes so far except for Hive. Today sat with a colleague here to disable Canary and still found that Hive Metastore was going down. Repeated restarts from the CM appear to restart HS2 and Metastore successfully followed with an immediate shut down - throwing an error message pointing to KMS. I did add KMS too to check if it would solve the issue but even KMS addition didnt solve the issue. 

Upon checking further we found that HS2 and HM logs were not getting updated past yesterday midnight. So we removed those files and started the Hive HS2 and HM processes again and could finally see that HS2 and HM start without issues.

We further think that the issue is due to zombie java processes that seem to have a lock effect on the log files thus somehow blocking the restart of Hive processes through CM. Suprisingly enough CM doesnt give a warning when it is actually not able to start the processes instead it ends showing a green mark.

We know docker shouldnt be compared with the real time OS or per say this was our own Docker that we built for our internal testing. But we do see the same issue i.e. agents actually not doing what they claim to be doing: eg - starting Hive processes even in the latest Cloudera Quickstart docker image.

I hope our experience helps someone struggling with similar issues.

Thanks for your response though.

Kabeer.

[#6]

And if someone is wondering what is the java defunct processes (zombie processes) that I am talking about then the link of docker that goes into specifics of the issue is - https://github.com/docker/docker/issues/18502

[#7]

I am also facing the same issue With CDH 5.7.0. Were you able to solve this issue?

[#8]

Kindly let me know what you mean when you mention that you too are facing similar issue.

As pointed by Harsh and as I have already mentioned, I see this is a non-issue and I have moved on.