autosleep use of deprecated logging-endpoint, fails fetching app activity, and never stop apps

[gberche-orange]

We observe the following stack trace:

2016-11-10T15:37:21.75+0100 [APP/0]      OUT Caused by: com.fasterxml.jackson.databind.JsonMappingException: Can not deserialize instance of java.util.LinkedHashMap out of VALUE_NUMBER_INT token
2016-11-10T15:37:21.75+0100 [APP/0]      OUT  at [Source: 404 Not Found: Requested route ('loggregator.[...]') does not exist.
2016-11-10T15:37:21.75+0100 [APP/0]      OUT ; line: 1, column: 1]
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:148)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.DeserializationContext.mappingException(DeserializationContext.java:857)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.DeserializationContext.mappingException(DeserializationContext.java:853)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.deser.std.StdDeserializer._deserializeFromEmpty(StdDeserializer.java:875)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:337)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:26)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3736)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2726)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         at org.cloudfoundry.spring.client.v2.CloudFoundryExceptionBuilder.build(CloudFoundryExceptionBuilder.java:42)
2016-11-10T15:37:21.75+0100 [APP/0]      OUT         ... 15 common frames omitted
2016-11-10T15:37:22.25+0100 [APP/0]      OUT ERROR - pool-1-thread-3 - o.c.a.w.ApplicationStopper(136) - unsuspected error
2016-11-10T15:37:22.25+0100 [APP/0]      OUT java.lang.IllegalStateException: subscriber timed out
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.waitForResult(CloudFoundryApi.java:439)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.getApplicationActivity(CloudFoundryApi.java:249)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.worker.ApplicationStopper.handleApplicationEnrolled(ApplicationStopper.java:120)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.worker.ApplicationStopper.lambda$run$1(ApplicationStopper.java:197)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.util.ApplicationLocker.executeThreadSafe(ApplicationLocker.java:47)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at org.cloudfoundry.autosleep.worker.ApplicationStopper.run(ApplicationStopper.java:190)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2016-11-10T15:37:22.25+0100 [APP/0]      OUT         at java.lang.Thread.run(Thread.java:745)

As a result, applications are never put to sleep.

This seems to come from the fact that autosleep uses the 2.0.0.M1 version of cf-java-client (see #252 ) which was using a deprecated version of the logging endpoint logging_endpoint and not the new doppler_logging_endpoint

Starting with v244,

From this release onwards, Loggregator is no longer registering it legacy logging_endpoint 
with the router. This makes the legacy endpoints on Traffic Controller unaccessible.

See related https://www.pivotaltracker.com/story/show/129384577 remove legacy endpoint from cf-release

The current cf-java-client does seem to use the new doppler endpoint, see https://github.com/cloudfoundry/cf-java-client/blob/v2.0.2.RELEASE/cloudfoundry-client-reactor/src/main/java/org/cloudfoundry/reactor/doppler/_ReactorDopplerClient.java#L80

However, it seems that upgrade to latest client #252 is still blocked on https://github.com/cloudfoundry/cf-java-client/issues/551

Alternatives:

• contribute a fix for https://github.com/cloudfoundry/cf-java-client/issues/551 to update to cf-java-client latest release (currently 2.0.2.RELEASE)
• provide a pluggeable way to fetch app recent activity with an alternative to doppler recentlogs endpoint, being the firehose endpoint (which however requires firehose.user scope and hence prevent usage of autosleep on a public CF instance such as bluemix or PWS)

[gberche-orange]

Refinining the alternatives for this issue as well as #187 :

• [ ] contribute a fix for https://github.com/cloudfoundry/cf-java-client/issues/551 to update to cf-java-client latest release (currently 2.0.2.RELEASE). More details into https://github.com/cloudfoundry-community/autosleep/issues/252#issuecomment-262484004

• [ ] provide a pluggeable way to fetch app recent activity with an alternative to doppler recentlogs endpoint

  • [ ] firehose: precise endpoint/data used to measure app activity:

    • documentation:
      • https://github.com/cloudfoundry/loggregator/blob/develop/src%2Ftrafficcontroller%2FREADME.md#endpoints
      • https://github.com/cloudfoundry/dropsonde-protocol/blob/master/events/README.md
    • per app streaming ( /apps/APP_ID/stream endpoint)
      • pros:
        • more efficient for a small proportion of watched apps (autosleep streams data for only enrolled apps )
        • limits data exposure to autosleep to only enrolled apps
      • cons: does not scale well with large number of enrolled apps (likely to require on TCP cnx per enrolled app + potentially one thread)
    • per Cf instance firehose stream ( /firehose/SUBSCRIPTION_ID )
      • pros:
        • more efficient with a large number of enrolled apps: a single TCP cnx and a single thread to consomme them, or possibly a cluster
        • precise HttpStartStop metric for incoming traffic (without )
      • cons:
        • will stream all CF metrics which is too high volume for autosleep itself. Would require to mutualize this metrics streaming with other systems such as prometheus or its CF exporter
        • not yet per-app gorouter metrics available see http://docs.cloudfoundry.org/loggregator/all_metrics.html#routing
    • [ ] Verify implications of the firehose approach
      • [ ] functional impacts: firehose requires firehose.user oauth scope which is only available to paas operators. This therefore does not address the issue for running autosleep public paas instances (as bluemix or PWS) as a private service broker.
      • [ ] performance impact: on large organizations with unenrolled many apps, the dedicated autosleep firehose streaming for autosleep represents high bandwidth and associated computing resource usage.
    • [ ] Refactor implementation of CloudFoundryApiService so that ApplicationActivity getApplicationActivity(String appUid) throws CloudFoundryException; be provided by the firehose client https://github.com/cloudfoundry-community/snotel
      • [ ] check potential spring dependency conflict
    • [ ] write an integration test (leveraging the acceptance tests prereqs) for checking correctness and accuracy

  • [ ] derived, aggregated time-series data from the firehose endpoint (such as prometheus time series db)

    • [ ] Identify relevant events to aggregate in time series:
      • HTTPStartStop per app: ie applicationId != null, index fields: start/stop timestamp, (+ potential finite value fields: method, statusCode, instanceIndex)
      • LogMessage per app, ie source_type=APP, app_id !=null
    • [ ] Check support in prometheus nozzle exporter: HttpStartStop events are not currently collected, they are filtered out
      • https://github.com/cloudfoundry-community/firehose_exporter/blob/master/README.md Comma separated events to filter (ContainerMetric, CounterEvent, ValueMetric)
      • https://github.com/cloudfoundry-community/firehose_exporter/blob/master/filters/event_filter_test.go#L24-L44
      • https://github.com/cloudfoundry-community/firehose_exporter/blob/master/firehosenozzle/firehose_nozzle.go
    • [ ] Study prometheus API that autosleep could use

[gberche-orange]

Progress is being done by the cf-java-client team to have a reliable "recentLog" support, remaining dependent issue is tracked on https://github.com/cloudfoundry/cf-java-client/issues/672