host monitor log full of ERROR com.cloudera.cmf.BasicScmProxy: Failed request to SCM: 302

[#1]

RedHat 6.7

Parcel: 5.7.0-1.cdh5.7.0.p0.45

RPMs:

cloudera-manager-server-5.7.0-1.cm570.p0.76.el6.x86_64
cloudera-manager-agent-5.7.0-1.cm570.p0.76.el6.x86_64
cloudera-manager-daemons-5.7.0-1.cm570.p0.76.el6.x86_64

host monitor is running and the cluster is green, no issues.

however the event log full of chatter/noise, and this is one of the issues reported over and over.

# tail -n 100 /var/log/cloudera-scm-firehose/mgmt-cmf-mgmt-HOSTMONITOR-hostname.log.out

2016-08-24 15:45:47,969 ERROR com.cloudera.cmf.BasicScmProxy: Failed request to SCM: 302
2016-08-24 15:45:48,969 INFO com.cloudera.cmf.BasicScmProxy: Authentication to SCM required.
2016-08-24 15:45:49,027 INFO com.cloudera.cmf.BasicScmProxy: Using encrypted credentials for SCM
2016-08-24 15:45:49,031 INFO com.cloudera.cmf.BasicScmProxy: Authenticated to SCM.
2016-08-24 15:47:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T20:47:55.591Z, forMigratedData=false
2016-08-24 15:49:56,764 INFO com.cloudera.cmon.tstore.leveldb.LDBResourceManager: Closed: 0 partitions
2016-08-24 15:52:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T20:52:55.591Z, forMigratedData=false
2016-08-24 15:52:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Starting rollup from raw to rollup=TEN_MINUTELY for rollupTimestamp=2016-08-24T20:50:00.000Z
2016-08-24 15:52:56,438 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Finished rollup: duration=PT0.847S, numStreamsChecked=41065, numStreamsRolledUp=3228
2016-08-24 15:57:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T20:57:55.591Z, forMigratedData=false
2016-08-24 15:59:56,767 INFO com.cloudera.cmon.tstore.leveldb.LDBResourceManager: Closed: 0 partitions
2016-08-24 16:02:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T21:02:55.591Z, forMigratedData=false
2016-08-24 16:02:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Starting rollup from raw to rollup=TEN_MINUTELY for rollupTimestamp=2016-08-24T21:00:00.000Z
2016-08-24 16:02:56,527 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Finished rollup: duration=PT0.936S, numStreamsChecked=41065, numStreamsRolledUp=3228
2016-08-24 16:02:56,527 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Starting rollup from ts_stream_rollup_PT600S to rollup=HOURLY for rollupTimestamp=2016-08-24T21:00:00.000Z
2016-08-24 16:02:57,381 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Finished rollup: duration=PT0.854S, numStreamsChecked=41065, numStreamsRolledUp=3228
2016-08-24 16:07:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T21:07:55.591Z, forMigratedData=false
2016-08-24 16:09:56,772 INFO com.cloudera.cmon.tstore.leveldb.LDBResourceManager: Closed: 0 partitions
2016-08-24 16:12:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-08-24T21:12:55.591Z, forMigratedData=false
2016-08-24 16:12:55,591 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Starting rollup from raw to rollup=TEN_MINUTELY for rollupTimestamp=2016-08-24T21:10:00.000Z
2016-08-24 16:12:56,282 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Finished rollup: duration=PT0.691S, numStreamsChecked=41065, numStreamsRolledUp=3228
2016-08-24 16:16:47,102 ERROR com.cloudera.cmf.BasicScmProxy: Failed request to SCM: 302
2016-08-24 16:16:48,103 INFO com.cloudera.cmf.BasicScmProxy: Authentication to SCM required.
2016-08-24 16:16:48,160 INFO com.cloudera.cmf.BasicScmProxy: Using encrypted credentials for SCM
2016-08-24 16:16:48,165 INFO com.cloudera.cmf.BasicScmProxy: Authenticated to SCM.

[#2 · Accepted solution]

Hi,

The "Failed request to SCM: 302" message occurs when the Host Monitor attempts to communicate to Cloudera Manager but the session has expired.  The Host Monitor acts as a client that authenticates to SCM, so it is subject to session restrictions.

The error can be ignored as the Host Monitor will re-authenticate and we do see that in your case that occurs.

In fact, a code change to make the message an INFO message rather than ERROR is slated for Cloudera Manager 5.7.2 and 5.8.2. 

[#3]

Hi

I am getting the similar issue (Failed request to SCM: 302). I understand from your comment that we can ignore this issue but my questions are

a. Is there any way to fix this issue?

b. If not,  This issue send an alert message to our distribution group for every 5 minutes (end-up with 100s of mail by eod everyday). Is it OK to disable (only) this alert message to avoid the mail junk? if so, how to disable (only) this alert?

CDH version 5.4

1. cd /var/log/cloudera-scm-firehose
sudo tail -100 mgmt-cmf-mgmt-SERVICEMONITOR-<hostname>.com.log.out

2016-09-01 13:16:31,995 INFO hive.metastore: Trying to connect to metastore with URI thrift://<hostname>:9083
2016-09-01 13:16:31,996 INFO hive.metastore: Opened a connection to metastore, current connections: 1
2016-09-01 13:16:31,996 INFO hive.metastore: Connected to metastore.
2016-09-01 13:16:32,665 INFO hive.metastore: Closed a connection to metastore, current connections: 0
2016-09-01 13:19:24,750 ERROR com.cloudera.cmf.BasicScmProxy: Failed request to SCM: 302
2016-09-01 13:19:25,749 INFO com.cloudera.cmf.BasicScmProxy: Authentication to SCM required.
2016-09-01 13:19:25,815 INFO com.cloudera.cmf.BasicScmProxy: Using encrypted credentials for SCM
2016-09-01 13:19:25,818 INFO com.cloudera.cmf.BasicScmProxy: Authenticated to SCM.
2016-09-01 13:20:09,250 INFO com.cloudera.cmon.tstore.leveldb.LDBPartitionManager: Expiring partition LDBPartitionMetadataWrapper{tableName=type, partitionName=type_2016- 08-31T05:11:09.207Z, startTime=2016-08-31T05:11:09.207Z, endTime=2016-08-31T05:41:09.207Z, version=2, state=CLOSED}


2. cd /var/log/cloudera-scm-firehose
sudo tail -500 mgmt-cmf-mgmt-HOSTMONITOR-eqa-<hostname>.log.out

2016-09-01 13:15:10,693 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-09-01T17:15:10.693Z, forMigratedData=false
2016-09-01 13:17:24,683 ERROR com.cloudera.cmf.BasicScmProxy: Failed request to SCM: 302
2016-09-01 13:17:25,683 INFO com.cloudera.cmf.BasicScmProxy: Authentication to SCM required.
2016-09-01 13:17:25,749 INFO com.cloudera.cmf.BasicScmProxy: Using encrypted credentials for SCM
2016-09-01 13:17:25,752 INFO com.cloudera.cmf.BasicScmProxy: Authenticated to SCM.
2016-09-01 13:20:10,693 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Running the LDBTimeSeriesRollupManager at 2016-09-01T17:20:10.693Z, forMigratedData=false
2016-09-01 13:20:10,693 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Starting rollup from raw to rollup=TEN_MINUTELY for rollupTimestamp=2016-09-01T17:20:00.000Z
2016-09-01 13:20:11,654 INFO com.cloudera.cmon.tstore.leveldb.LDBTimeSeriesRollupManager: Finished rollup: duration=PT0.961S, numStreamsChecked=41773, numStreamsRolledUp=4448

3. Alert message from Cloudera Manager

The health test result for NAVIGATORMETASERVER_SCM_HEALTH has become bad: This role's process is starting. This role is supposed to be started.
Time: Sep 1, 2016 11:52:29 AM
View Details on <hostname>
Monitor Startup: false
Role: Navigator Metadata Server (<hostname>)
Role Type: Navigator Metadata Server
Cluster: <Clustername>
Cluster Display Name: <Clustername>
Service: mgmt
Service Display Name: mgmt
Service Type: Cloudera Management Service
Hosts: <Hostname>
Health Test Results: The health test result for NAVIGATORMETASERVER_SCM_HEALTH has become bad: This role's process is starting. This role is supposed to be started

Thanks

Kumar

[#4]

The best thing to do here is to upgrade to Cloudera Manager 5.7.2 or higher since this is resolved.

What do the alerts you see look like.  You added an alert for Navigator that is not related to this issue and probably needs its own thread for investigation.  It appears Navigator Metadata Server is crashing.

Are you sure that the alerts every 5 minutes are from the error 302 event?  Can you show us?

Thanks,

Ben

[#5]

Thank you Ben... 

It is my bad that i've mentioned a wrong CDH version. The actual version is CDH 5.7.0

I've opened a new topic, link as follows

https://community.cloudera.com/t5/Cloudera-Manager-Installation/NAVIGATORMETASERVER-SCM-HEALTH-has-b...

Also i've copy pasted the log from the following path : Cloudera manager -> mgmt -> quick links -> Alert