This discussion is archived
6 Replies Latest reply: Nov 6, 2012 12:50 PM by BrianP RSS

EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart

BrianP Journeyer
Currently Being Moderated
Hi all,

EM12cR2 on Linux x86-64 w/an 11.2.0.3 repository database. Just reporting this on the forum so others don't spend a bunch of time trying to chase it down.

Since about an hour before the transition from daylight savings time back to standard time, I've noticed some events showing up in the incident manager that make it appear as though my agents are time traveling.

The events are showing up as metric evaluation errors on database instance and agent targets stating, for example: "Row(8): Supplied date is in the future : now = Mon Nov 05 08:42:41 EST 2012 supplied value = Mon Nov 05 09:38:42 EST 2012". Sometimes the times reported are exactly one hour apart: "Row(1): Supplied date is in the future : now = Sun Nov 04 01:59:52 EDT 2012 supplied value = Sun Nov 04 01:59:52 EST 2012". I see these from the repository database instance, several monitored database instances, and four different agents.

I'm seeing cases where a monitored database instance has this event and the monitoring agent does NOT, and I'm also seeing cases where both a monitored database and the agent performing the monitoring both show the event.

It seems that stopping the agent, running an emctl clearstate agent, then starting up the agent again on each affected server will, after a few minutes, cause these events to clear. I only noticed this right when it started since I was logged in to take down SAP instances that can't handle the time change, I wasn't expecting to hit a related problem with EM12c.
  • 1. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    rpatti Explorer
    Currently Being Moderated
    FYI, these errors have been tracked down to a bug. Dev has confirmed that the errors should auto-clear on next evaluation.
    I hit the same issue on my local box and can also see that they clear on their own. Hope that helps.
  • 2. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    BrianP Journeyer
    Currently Being Moderated
    Thanks! I had figured many/most of them would clear with the next metric evaluation, but I know some of them were triggered at 2:00AM on Sunday morning and hadn't cleared by 9AM on Monday morning (31 hours later) -- could be I was looking at metrics that are evaluated less frequently than every 24 hours.
  • 3. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    rpatti Explorer
    Currently Being Moderated
    It these errors persist beyond the next evaluation - I would recommend creating an SR in case there is another symptom that did not show up in our local views.
    In the interim, may be you can post the specifics of the metrics - the target type, metric name and the message should help. Thanks.
  • 4. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    BrianP Journeyer
    Currently Being Moderated
    An incident manager search for recent events of type 'metric evaluation error' isn't returning any results, but I think I've found this info in MGMT$METRIC_ERROR_HISTORY. I first tried restarting the agents and that cleared many of the errors, but several didn't go away until I ran a clearstate as well.

    I commented out the "having max(collection_timestamp) >= '11/05/2012 08:00'" clause in the SQL below since that excluded the evaluation errors that showed up for EMDStatus/EMDAdditionalStatus on the oracle_emd (agent) targets, and those are the ones that I absolutely remember seeing for more than 24 hours -- the collection frequency for EMDStatus/EMDAdditionalStatus is set to one minute so it seems like it only threw the evaluation error during the one hour window around the time change, but they didn't clear until I did the clearstate on each around 9AM Monday Nov 5th.
      1  select target_type, metric_name, min(collection_timestamp), max(collection_timestamp)
      2  from mgmt$metric_error_history
      3  where error_message like '%in the future%'
      4  and collection_timestamp >= '11/03/2012 00:00'
      5  group by target_type, metric_name
      6  --having max(collection_timestamp) >= '11/05/2012 08:00'
      7* order by target_type, metric_name
    SQL> /
    
    TARGET_TYPE     METRIC_NAME                    MIN(COLLECTION_TIME MAX(COLLECTION_TIME
    --------------- ------------------------------ ------------------- -------------------
    oracle_database Database_Resource_Usage        11/04/2012 01:02:11 11/05/2012 09:02:04
    oracle_database UserBlock                      11/04/2012 02:16:13 11/05/2012 05:13:25
    oracle_database alertLog                       11/04/2012 01:48:31 11/04/2012 01:48:31
    oracle_database file                           11/04/2012 01:02:35 11/05/2012 09:01:03
    oracle_database instance_efficiency            11/04/2012 01:02:11 11/05/2012 09:00:33
    oracle_database instance_throughput            11/04/2012 01:01:40 11/05/2012 09:01:54
    oracle_database service                        11/04/2012 01:00:15 11/05/2012 08:57:29
    oracle_database system_response_time_per_call  11/04/2012 01:02:12 11/05/2012 08:59:29
    oracle_database wait_bottlenecks               11/04/2012 01:01:10 11/05/2012 08:59:49
    oracle_database wait_sess_cls                  11/04/2012 01:02:12 11/05/2012 08:59:12
    oracle_emd      EMDAdditionalStatus            11/04/2012 01:00:03 11/04/2012 01:59:57
    
    TARGET_TYPE     METRIC_NAME                    MIN(COLLECTION_TIME MAX(COLLECTION_TIME
    --------------- ------------------------------ ------------------- -------------------
    oracle_emd      EMDStatus                      11/04/2012 01:00:03 11/04/2012 01:59:52
    
    12 rows selected.
    The error_messages were all variations of the following, differing only in the Row(N) number reported and the precise datestamps.

    "oracle.sysman.emSDK.agent.fetchlet.exception.FetchletException: Row(1): Supplied date is in the future : now = Sun Nov 04 01:00:14 EDT 2012 supplied value = Sun Nov 04 01:00:14 EST 2012"

    I'm willing to file an SR if you think there's enough history available in the repository and/or logs to trace this back, but support might be better off if someone out there still has these evaluation errors showing as live in their system that could file an SR.

    I have a few XML files from the time change window sitting in $AGENT_INSTANCE_HOME/sysman/emd/upload/upload/badfile along with corresponding gcagent.log entries showing the upload was rejected:

    2012-11-04 01:00:20,312 [39:C09F1B75] WARN - Upload file /oraagent/agent12c/agent_inst/sysman/emd/upload/upload/sending/uplB_P2_S0_I4896.xml with tracking key 4896.1352008820000 being moved to invalid file location storage due to upload error
    oracle.sysman.gcagent.upload.UploadStoreForward$dequeuer$ResponseINTERNALException: ORA-20001: publish_metric_error Failed: (target guid = 78BF0406DB756EFB3D13C54A7D79BD2F)(metric guid = 02E6966E2B392880F60FFB9FEF5D30C4)(Coll name = EMDStatusCollection)(Event name = EMDStatus)(error_msg = )ORA-20391: [EVEM_ERR_REP_DATE_LT_PREV: :Reported date should not be earlier than reported date of previous event.]
  • 5. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    rpatti Explorer
    Currently Being Moderated
    Thanks Brian. Checked with the agent dev team - I don't think we need another SR. All of these rows are covered by the bug already filed.
  • 6. Re: EM12c "Supplied date is in the future" DST fix w/agent clearstate/restart
    BrianP Journeyer
    Currently Being Moderated
    Sounds good to me. If I can do anything else to help, just let me know, but it sounds like you've all got it covered.