Failing to create-service when autosleep hosted behind buddy-broker for --shared-scope

[drnic]

I've deployed the autosleep apps from master branch to api.run.pivotal.io

In order to expose autosleep broker to all starkandwayne.com's run.pivotal.io organization spaces, I've put it behind https://github.com/cloudfoundry-community/buddy-broker This broker allows a single shared broker to be uniquely registered in every different space (unique name, and UUIDs). Buddy broker might be the root cause of the issue (perhaps not passing thru parameters); but I'm not sure yet.

In the stannis space, the autosleep broker is registered as the autosleep-starkandwayne-starkandwayne-stannis,

$ cf create-service autosleep-starkandwayne-starkandwayne-stannis default autosleep -c '{"auto-enrollment": "forced"}'
Creating service instance autosleep in org starkandwayne / space stannis as drnic@starkandwayne.com...
FAILED
Server error, status code: 502, error code: 10001, message: Service broker error: Could not read document: Can not instantiate value of type [map type; class java.util.LinkedHashMap, [simple type, class java.lang.String] -> [simple type, class java.lang.Object]] from String value ('eyJhdXRvLWVucm9sbG1lbnQiOiJmb3JjZWQifQ=='); no single-String constructor/factory method
 at [Source: java.io.PushbackInputStream@5001117e; line: 1, column: 213] (through reference chain: org.springframework.cloud.servicebroker.model.CreateServiceInstanceRequest["parameters"]); nested exception is com.fasterxml.jackson.databind.JsonMappingException: Can not instantiate value of type [map type; class java.util.LinkedHashMap, [simple type, class java.lang.String] -> [simple type, class java.lang.Object]] from String value ('eyJhdXRvLWVucm9sbG1lbnQiOiJmb3XXXXXX=='); no single-String constructor/factory method
 at [Source: java.io.PushbackInputStream@5001117e; line: 1, column: 213] (through reference chain: org.springframework.cloud.servicebroker.model.CreateServiceInstanceRequest["parameters"])

I tried to turn on debugging but I do not see any additional logs explaining the error in autowakeup-app to help with debugging.

cf set-env autosleep-app autosleep.debug autosleep
cf restart autosleep-app

Update 1: Reviewing the buddy-broker provision pass-thru/proxy code, I don't see how the parameters might be broken at a glance https://github.com/cloudfoundry-community/buddy-broker/blob/master/buddy/handler.go#L79-L128

[gberche-orange]

Would make sense to trace the provision request proxified by the buddy broker as it reaches the autosleep app, maybe consider adding a verbose trace mode to buddy broker ?

Maybe the https://github.com/cloudfoundry-samples/logging-route-service could be mapped to the autosleep route to trace incoming traffic.

On the autosleep side, you might have luck with spring traces, or possibly further down such as tomcat.

There used to have support for dumping requests in tomcat, but it was broken last time I tested it, see https://groups.google.com/a/cloudfoundry.org/d/msg/vcap-dev/8bm0IDAZNHU/MS3yUN3whm0J

Maybe the TRACE actuator endpoint could provide you detailed traces of the last recorded 1000 requests, I haven't tested it yet on autosleep though.

The -Dautosleep.debug=spring would turn spring traces https://github.com/cloudfoundry-community/autosleep/blob/08f8d663dea272799d5556c1ed83c1327e490d31/common/src/main/resources/logback.xml#L39-L48

Otherwise you can select individual log level through the JAVA_OPTS option https://github.com/cloudfoundry-community/autosleep/blob/180f4f1ac0dfdfa3f04c9a1bd35acd997f3f8f4f/manifest.tmpl.yml#L18-L19

Please let us know how you diagnosed this, so we can document it for other diagnostics

[drnic]

I tried out the logging-route-service but hit a DNS/cloudflare issue https://github.com/cloudfoundry-samples/logging-route-service/issues/3

Seen this before?

[drnic]

Ok, worked around the cloudflare issue by using cfapps.io domain for autosleep/autowakeup-app.

I can now see that buddy-broker is mis-processing the parameters being passed thru.

The logging-route logs incoming into buddy-broker: are:

2017-01-08T15:21:42.98-0800 [APP/PROC/WEB/0]OUT 2017/01/08 23:21:42 Request Body: {"service_id":"3e02929c-d253-11e6-8921-032a782f98e5-starkandwayne-stannis","plan_id":"41e3ba08-d253-11e6-a8b0-67ab01c15319-starkandwayne-stannis","organization_guid":"f18dd8a3-bea3-4078-953a-e3a768520818","space_guid":"b7d9e138-23b0-4578-b81e-181c11afd524","parameters":{"auto-enrollment":"forced"}}

But when the request is forwarded on to autosleep-app, the parameters are misencoded:

2017-01-08T15:28:03.57-0800 [APP/PROC/WEB/0]OUT 2017/01/08 23:28:03 Request Body: {"service_id":"3e02929c-d253-11e6-8921-032a782f98e5","plan_id":"41e3ba08-d253-11e6-a8b0-67ab01c15319","organization_guid":"f18dd8a3-bea3-4078-953a-e3a768520818","space_guid":"b7d9e138-23b0-4578-b81e-181c11afd524","parameters":"eyJhdXRvLWVucm9sbG1lbnQiOiJmb3JjZWQifQ=="}

Closing the issue; and moving it to buddy-broker repo https://github.com/cloudfoundry-community/buddy-broker/issues/3

[gberche-orange]

thanks @drnic for sharing the diagnostic procedure and outcome.

I'm not sure to understand why the logging route service issue with the cloudflare error symptom triggers on autosleep.starkandwayne.com and not autosleep.cfapps.io.