CFv2 web services not talking to each other

190 views
Skip to first unread message

Barry Williams

unread,
Jul 16, 2013, 11:21:57 AM7/16/13
to bosh-...@cloudfoundry.org
Hey all,
I am working on deploying CFv2 on vSphere 5.1
It deploys "successfully" but we can't use the deployment made.

Basically the issue we are having is that the CF command line can target it, but can't login.  We are having other issues, but we feel they are all related.  It seems the root of the problem is that many of the web services are run on port 8080, when all services expect each other to be running on port 80.  For example, everything on uaa is being run from port 8080, but the api job (with cc and gorouter) seems to expect them to run on port 80, so the services don't seem to be talking to each other.

A note about our deployment manifest: Since I wasn't able to find a CFv2 manifest for vSphere anywhere (at least one that worked), I cooked my own by merging CFv2 manifests for OpenStack and AWS. This is probably the source of our problem, but I was hoping to get some opinions and advice on what to do.

Thanks,
Barry

Info:

Bosh CLI: BOSH 1.5.0.pre.805

$bosh status
Config
             /home/wglabs/.bosh_config

Director
  Name       bosh
  URL        http://192.168.151.14:25555
  Version    0.7 (release:fb1aebb0 bosh:20f2ca20)
  User       admin
  UUID       0a050bd1-3eda-4870-b6ba-8fd11e9a63e3
  CPI        vsphere
  dns        disabled

Deployment
  Manifest   /home/wglabs/deployments/cf_v2_merged.yml

Stemcell:  bosh-stemcell 1.5.0.pre2

BOSH Release: bosh 11
CF Release: cf-release 133

Deployment Manifest:
---
name: cf
director_uuid: 0a050bd1-3eda-4870-b6ba-8fd11e9a63e3

releases:
 - name: cf-release
   version: 133

compilation:
  workers: 4
  network: default
  reuse_compilation_vms: true
  cloud_properties:
    ram: 2048
    disk: 8096
    cpu: 2

update:
  canaries: 1
  canary_watch_time: 30000-900000
  update_watch_time: 30000-900000
  max_in_flight: 4
  max_errors: 1

networks:
- name: default
  subnets:
  - range: 192.168.151.0/24
    reserved:
    - 192.168.151.2 - 192.168.151.149
    - 192.168.151.251 - 192.168.151.254 #reserved for lb BW
    static:
    - 192.168.151.200 - 192.168.151.250
    gateway: 192.168.151.1
    dns:
    - 192.168.200.10
    - 192.168.200.11
    cloud_properties:
      name: sandbox-vlan151
- name: lb
  subnets:
  - range: 192.168.151.0/24
    static:
    - 192.168.151.251 - 192.168.151.254
    dns:
    - 192.168.200.10
    - 192.168.200.11
    cloud_properties:
      name: sandbox-vlan151 #this can go on another vlan in the future BW

resource_pools:
  - name: small
    network: default
    size: 2
    stemcell:
      name: bosh-stemcell
      version: 1.5.0.pre2
    cloud_properties:
      ram: 1024 #4096
      disk: 6000 #8192
      cpu: 1
    env:
      bosh:
        password: $6$2f6qtRfO$oJOeKk/ZDNb7PWnvMiXDC/HstKiLiZCBHP32KHFVeM9rXgs4W/JJiI4a/eHoddhxJzorLYgi2JUQiOKxZko4M.
      
  - name: medium
    network: default
    size: 2
    stemcell:
      name: bosh-stemcell
      version: 1.5.0.pre2
    cloud_properties:
      ram: 4096
      disk: 8192
      cpu: 1
    env:
      bosh:
        password: $6$2f6qtRfO$oJOeKk/ZDNb7PWnvMiXDC/HstKiLiZCBHP32KHFVeM9rXgs4W/JJiI4a/eHoddhxJzorLYgi2JUQiOKxZko4M.

jobs:
  - name: core
    template:
      - syslog_aggregator
      - nats
      - postgres
      - health_manager_next
      - collector
      - debian_nfs_server
      - login
    instances: 1
    resource_pool: medium
    persistent_disk: 16384
    networks:
      - name: default
        default: [dns, gateway]
        static_ips:
          - 192.168.151.201
    properties:
      db: databases
      cc_props: ccng
      hm_props: health_manager_ccng

  - name: uaa
    template:
      - uaa
    instances: 1
    resource_pool: small
    networks:
      - name: default
        default: [dns, gateway]
        static_ips:
          - 192.168.151.202

  - name: api
    template:
      - cloud_controller_ng
      - gorouter
    instances: 1
    resource_pool: medium
    networks:
    - name: default
      default:
      - dns
      - gateway
      static_ips:
      - 192.168.151.203
    - name: lb
      static_ips:
      - 192.168.151.251
    properties:
      db: databases

  - name: dea
    template:
      - dea_next
    instances: 1
    resource_pool: small
    networks:
      - name: default
        default: [dns, gateway]

properties:
  domain: cf.sandbox.wglabs.local
  system_domain: cf.sandbox.wglabs.local
  system_domain_organization: "cf"
  app_domains:
    - cf.sandbox.wglabs.local

  networks:
    apps: default
    management: default

  nats:
    address: 192.168.151.201
    port: 4222
    user: nats
    password: "c1oudc0w"
    authorization_timeout: 5

  router:
    port: 8081
    status:
      port: 8080
      user: gorouter
      password: "c1oudc0w"

  dea: &dea
    max_memory: 4096
    memory_mb: 4084
    memory_overcommit_factor: 4
    disk_mb: 16384
    disk_overcommit_factor: 4

  dea_next: *dea

  service_lifecycle:
    serialization_data_server:
    - 192.168.151.205

  syslog_aggregator:
    address: 192.168.151.201
    port: 54321

  serialization_data_server:
    port: 8080
    logging_level: debug
    upload_token: 8f7COGvThwlmulIzAgOHxMXurBrG364k
    upload_timeout: 10

  collector:
    deployment_name: cf
    use_tsdb: false
    use_aws_cloudwatch: false
    use_datadog: false

  nfs_server:
    address: 192.168.151.201
    #network: "*.cf.microbosh"
    #idmapd_domain: iad1

  debian_nfs_server:
    no_root_squash: true

  databases: &databases
    db_scheme: postgres
    address: 192.168.151.201
    port: 5524
    roles:
      - tag: admin
        name: ccadmin
        password: "c1oudc0w"
      - tag: admin
        name: uaaadmin
        password: "c1oudc0w"
    databases:
      - tag: cc
        name: ccdb
        citext: true
      - tag: uaa
        name: uaadb
        citext: true

  ccdb: &ccdb
    db_scheme: postgres
    address: 192.168.151.201
    port: 5524
    roles:
      - tag: admin
        name: ccadmin
        password: "c1oudc0w"
    databases:
      - tag: cc
        name: ccdb
        citext: true

  ccdb_ng: *ccdb

  uaadb: 
    db_scheme: postgresql
    address: 192.168.151.201
    port: 5524
    roles:
      - tag: admin
        name: uaaadmin
        password: "c1oudc0w"
    databases:
      - tag: uaa
        name: uaadb
        citext: true

  cc_api_version: v2

  cc: &cc
    logging_level: debug
    external_host: ccng
    cc_partition: default
    db_encryption_key: "b963127302433579"
    bootstrap_admin_email: "ad...@cf.sandbox.wglabs.local"
    bulk_api_password: "c1oudc0w"
    uaa_resource_id: cloud_controller
    staging_upload_user: uploaduser
    staging_upload_password: c1oudc0w
    resource_pool:
      resource_directory_key: cc-resources
      fog_connection:
        provider: Local
        local_root: /var/vcap/shared
    packages:
      app_package_directory_key: cc-packages
    droplets:
      droplet_directory_key: cc-droplets

  ccng: *cc

  login:
    protocol: http
    links:
      
  health_manager_ccng:
    shadow_mode: disable
    cc_partition: ng
    
  uaa:
    spring_profiles: postgresql
    no_ssl: true
    catalina_opts: -Xmx768m -XX:MaxPermSize=256m
    resource_id: account_manager
    jwt:
      signing_key: |
        -----BEGIN RSA PRIVATE KEY-----
        MIICXAIBAAKBgQDHFr+KICms+tuT1OXJwhCUmR2dKVy7psa8xzElSyzqx7oJyfJ1
        JZyOzToj9T5SfTIq396agbHJWVfYphNahvZ/7uMXqHxf+ZH9BL1gk9Y6kCnbM5R6
        0gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9Qs0wBugspULZVNRxq7veq/fzwIDAQAB
        AoGBAJ8dRTQFhIllbHx4GLbpTQsWXJ6w4hZvskJKCLM/o8R4n+0W45pQ1xEiYKdA
        Z/DRcnjltylRImBD8XuLL8iYOQSZXNMb1h3g5/UGbUXLmCgQLOUUlnYt34QOQm+0
        KvUqfMSFBbKMsYBAoQmNdTHBaz3dZa8ON9hh/f5TT8u0OWNRAkEA5opzsIXv+52J
        duc1VGyX3SwlxiE2dStW8wZqGiuLH142n6MKnkLU4ctNLiclw6BZePXFZYIK+AkE
        xQ+k16je5QJBAN0TIKMPWIbbHVr5rkdUqOyezlFFWYOwnMmw/BKa1d3zp54VP/P8
        +5aQ2d4sMoKEOfdWH7UqMe3FszfYFvSu5KMCQFMYeFaaEEP7Jn8rGzfQ5HQd44ek
        lQJqmq6CE2BXbY/i34FuvPcKU70HEEygY6Y9d8J3o6zQ0K9SYNu+pcXt4lkCQA3h
        jJQQe5uEGJTExqed7jllQ0khFJzLMx0K6tj0NeeIzAaGCQz13oo2sCdeGRHO4aDh
        HH6Qlq/6UOV5wP8+GAcCQFgRCcB+hrje8hfEEefHcFpyKH+5g1Eu1k0mLrxK2zd+
        4SlotYRHgPCEubokb2S1zfZDWIXW3HmggnGgM949TlY=
        -----END RSA PRIVATE KEY-----
      verification_key: |
        -----BEGIN PUBLIC KEY-----
        MIGfMA0GCSqGSIb3DQEBAQUAA4GNADCBiQKBgQDHFr+KICms+tuT1OXJwhCUmR2d
        KVy7psa8xzElSyzqx7oJyfJ1JZyOzToj9T5SfTIq396agbHJWVfYphNahvZ/7uMX
        qHxf+ZH9BL1gk9Y6kCnbM5R60gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9Qs0wBug
        spULZVNRxq7veq/fzwIDAQAB
        -----END PUBLIC KEY-----
    cc:
      client_secret: "c1oudc0w"
    admin:
      client_secret: "c1oudc0w"
    batch:
      username: batchuser
      password: c1oudc0w
    client:
      autoapprove:
        - cf
        - vmc
        - my
        - micro
        - support-signon
        - login
    clients:
      login:
        override: true
        scope: openid
        authorities: oauth.login
        secret: c1oudc0w
        authorized-grant-types: authorization_code,client_credentials,refresh_token
        redirect-uri: http://login.cf.sandbox.wglabs.local
      support-services:
        scope: scim.write,scim.read,openid,cloud_controller.read,cloud_controller.write
        secret: ssosecretsso
        authorized-grant-types: authorization_code,client_credentials
        authorities: portal.users.read
        access-token-validity: 1209600
        refresh-token-validity: 1209600
      vmc:
        override: true
        authorized-grant-types: password,implicit
        authorities: uaa.none
        scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
      cf:
        override: true
        authorized-grant-types: password,implicit,refresh_token
        authorities: uaa.none
        scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
      servicesmgmt:
        override: true
        secret: serivcesmgmtsecret
        scope: openid,cloud_controller.read,cloud_controller.write
        authorities: uaa.resource,oauth.service,clients.read,clients.write,clients.secret
        authorized-grant-types: authorization_code,client_credentials,password,implicit
        autoapprove: true
    scim:
      users:
      - admin|c1oudc0w|scim.write,scim.read,openid,cloud_controller.admin
      - services|c1oudc0w|scim.write,scim.read,openid,cloud_controller.admin

Barry Williams

unread,
Jul 16, 2013, 11:29:37 AM7/16/13
to bosh-...@cloudfoundry.org
Here is how I am using CF:

wglabs@bosh-bootstrap:~$ cf target http://api.cf.sandbox.wglabs.local
wglabs@bosh-bootstrap:~$ cf login ad...@cf.sandbox.wglabs.local

CF::UAA::BadTarget: error: Connection refused - connect(2)
cat ~/.cf/crash # for more details
wglabs@bosh-bootstrap:~$ cf login admin

CF::UAA::BadTarget: error: Connection refused - connect(2)
cat ~/.cf/crash # for more details

Dr Nic Williams

unread,
Jul 16, 2013, 3:19:59 PM7/16/13
to bosh-users
Thoughts from looking at your deployment file:

You can remove the following from your resource_pools:
env:
    bosh:
        password

Your manifest looks like it is for v132 so change the release number to 132 instead of 133 (see earlier email about v133 changes).

Once you've deployed v132 (or extracted postgres & nfs jobs into their own job, say "data", which would need to be the first job), then let us know if you still have issues.

The next thing to check will be networking. Can each VM talk to each other? Are they talking to each other. Tail the logs within uaa & api jobs to check that they are registering with each other.

Nic


--
Dr Nic Williams
Stark & Wayne LLC - consultancy for Cloud Foundry users
twitter @drnic

Barry Williams

unread,
Jul 16, 2013, 8:16:45 PM7/16/13
to bosh-...@cloudfoundry.org


Nic,

I have moved postgres and nfs to a job called data (placed first).  I then redeployed with v133 - same issue. I redeployed as 132, and still the same.  I went and tailed the logs on UAA and API.

From what I see, it appears that api sees several machines registering themselves, but on uaa it looks like the only machines it's talking to is console (192.168.151.201) and itself.

Any ideas? I hope these logs can help.

Thanks,

Barry

Log Tail snippet from API:


2013-07-17_00:01:34.60767 #[685] DEBUG: Heartbeat delivered
2013-07-17_00:01:54.57972 #[685] INFO: Message: {"method"=>"ssh", "arguments"=>["setup", {"user"=>"bosh_7b1r9lhng", "public_key"=>"MIGfMA0GCSqGSIb3DQEBAQUAA4GNADCBiQKBgQDHFr+KICms+tuT1OXJwhCUmR2d\nKVy7psa8xzElSyzqx7oJyfJ1JZyOzToj9T5SfTIq396agbHJWVfYphNahvZ/7uMX\nqHxf+ZH9BL1gk9Y6kCnbM5R60gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9Qs0wBug\nspULZVNRxq7veq/fzwIDAQAB\n", "password"=>"6TKaJZu2nOf6w"}], "reply_to"=>"director.f924398a-612b-44f6-8fe7-668e223e35da.e0d8fba0-bf7a-4c6c-8ab0-aa5fb64a6be3"}
2013-07-17_00:01:54.58041 #[685] INFO: Setting up ssh for user bosh_7b1r9lhng
2013-07-17_00:01:54.76682 start: Job is already running: ssh
2013-07-17_00:01:54.77016 #[685] INFO: started sshd 2013-07-17 00:01:54 +0000
2013-07-17_00:01:54.77016 #[685] INFO: reply_to: director.f924398a-612b-44f6-8fe7-668e223e35da.e0d8fba0-bf7a-4c6c-8ab0-aa5fb64a6be3: payload: {:value=>{"command"=>"setup", "status"=>"success", "ip"=>"192.168.151.203"}}
2013-07-17_00:02:34.67355 #[685] INFO: Heartbeat sent
2013-07-17_00:02:34.67451 #[685] DEBUG: Heartbeat delivered
2013-07-17_00:03:34.75616 #[685] INFO: Heartbeat sent
2013-07-17_00:03:34.75697 #[685] DEBUG: Heartbeat delivered
2013-07-17_00:04:34.78023 #[685] INFO: Heartbeat sent
2013-07-17_00:04:34.78109 #[685] DEBUG: Heartbeat delivered
2013-07-17_00:05:34.88597 #[685] INFO: Heartbeat sent
2013-07-17_00:05:34.88666 #[685] DEBUG: Heartbeat delivered

==> /var/vcap/monit/monit.log <==
[UTC Jul 16 20:42:19] info     : monit: generated unique Monit id 9d374487d092f96fc9e35633a1d3e5f3 and stored to '/root/.monit.id'
[UTC Jul 16 20:42:19] info     : Starting monit daemon with http interface at [127.0.0.1:2822]
[UTC Jul 16 20:42:19] info     : Starting monit HTTP server at [127.0.0.1:2822]
[UTC Jul 16 20:42:19] info     : monit HTTP server started
[UTC Jul 16 20:42:19] info     : 'system_a913e4d7-2260-4416-8254-54377a84daba' Monit started
[UTC Jul 16 20:42:19] error    : Cannot open a connection to the mailserver '127.0.0.1:2825' -- Transport endpoint is not connected
[UTC Jul 16 20:42:19] error    : No mail servers are available
[UTC Jul 16 20:42:19] error    : Cannot open a connection to the mailserver '127.0.0.1:2825' -- Transport endpoint is not connected
[UTC Jul 16 20:42:19] error    : No mail servers are available
[UTC Jul 16 20:42:19] error    : Alert handler failed, retry scheduled for next cycle
[UTC Jul 16 20:45:16] info     : Reinitializing monit daemon
[UTC Jul 16 20:45:16] info     : Awakened by the SIGHUP signal
[UTC Jul 16 20:45:16] info     : Reinitializing monit - Control file '/var/vcap/bosh/etc/monitrc'
[UTC Jul 16 20:45:16] info     : Shutting down monit HTTP server
[UTC Jul 16 20:45:16] info     : monit HTTP server stopped
[UTC Jul 16 20:45:16] info     : Starting monit HTTP server at [127.0.0.1:2822]
[UTC Jul 16 20:45:16] info     : monit HTTP server started
[UTC Jul 16 20:45:16] info     : 'system_a913e4d7-2260-4416-8254-54377a84daba' Monit reloaded
[UTC Jul 16 20:45:22] info     : start service 'cloud_controller_ng' on user request
[UTC Jul 16 20:45:22] info     : Awakened by User defined signal 1
[UTC Jul 16 20:45:22] info     : 'cloud_controller_ng' start: /var/vcap/jobs/cloud_controller_ng/bin/cloud_controller_ng_ctl
[UTC Jul 16 20:45:22] info     : monit daemon at 1413 awakened
[UTC Jul 16 20:45:22] info     : start service 'nginx_ccng' on user request
[UTC Jul 16 20:45:22] info     : monit daemon at 1413 awakened
[UTC Jul 16 20:45:22] info     : start service 'gorouter' on user request
[UTC Jul 16 20:45:22] info     : monit daemon at 1413 awakened
[UTC Jul 16 20:45:23] info     : 'cloud_controller_ng' start action done
[UTC Jul 16 20:45:23] info     : 'nginx_ccng' start: /var/vcap/jobs/cloud_controller_ng/bin/nginx_ctl
[UTC Jul 16 20:45:24] info     : 'nginx_ccng' start action done
[UTC Jul 16 20:45:24] info     : 'gorouter' start: /var/vcap/jobs/gorouter/bin/gorouter_ctl
[UTC Jul 16 20:45:34] info     : 'gorouter' start action done
[UTC Jul 16 20:45:34] info     : Awakened by User defined signal 1

==> /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log <==
{"timestamp":1374019543.9021444,"message":"Sending registration: {:host=>\"192.168.151.203\", :port=>9022, :uris=>[\"ccng.cf.sandbox.wglabs.local\", \"api.cf.sandbox.wglabs.local\"], :tags=>{:component=>\"CloudController\"}}","log_level":"debug","source":"cf.registrar","data":{},"thread_id":19406520,"fiber_id":35479120,"process_id":8714,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.2.0/lib/cf/registrar.rb","lineno":95,"method":"send_registration_message"}

==> /var/vcap/sys/log/gorouter/gorouter.log <==
{"timestamp":1374019543.901935816,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.226 34567 [36c63a27e5590c7192d3b0c5e66d265a.cf.sandbox.wglabs.local] map[]  }","data":null}
{"timestamp":1374019543.904157162,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.203 9022 [ccng.cf.sandbox.wglabs.local api.cf.sandbox.wglabs.local] map[component:CloudController]  }","data":null}
{"timestamp":1374019544.918382883,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.201 8080 [login.cf.sandbox.wglabs.local] map[component:login]  }","data":null}
{"timestamp":1374019545.771356344,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.202 8080 [uaa.cf.sandbox.wglabs.local] map[component:uaa]  }","data":null}

==> /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log <==
{"timestamp":1374019548.9065614,"message":"Sending registration: {:host=>\"192.168.151.203\", :port=>9022, :uris=>[\"ccng.cf.sandbox.wglabs.local\", \"api.cf.sandbox.wglabs.local\"], :tags=>{:component=>\"CloudController\"}}","log_level":"debug","source":"cf.registrar","data":{},"thread_id":19406520,"fiber_id":35479120,"process_id":8714,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.2.0/lib/cf/registrar.rb","lineno":95,"method":"send_registration_message"}

==> /var/vcap/sys/log/gorouter/gorouter.log <==
{"timestamp":1374019548.908613443,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.226 34567 [36c63a27e5590c7192d3b0c5e66d265a.cf.sandbox.wglabs.local] map[]  }","data":null}
{"timestamp":1374019548.909212112,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.203 9022 [ccng.cf.sandbox.wglabs.local api.cf.sandbox.wglabs.local] map[component:CloudController]  }","data":null}
{"timestamp":1374019549.922304630,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.201 8080 [login.cf.sandbox.wglabs.local] map[component:login]  }","data":null}
{"timestamp":1374019550.772277355,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.202 8080 [uaa.cf.sandbox.wglabs.local] map[component:uaa]  }","data":null}

==> /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log <==
{"timestamp":1374019553.9087186,"message":"Sending registration: {:host=>\"192.168.151.203\", :port=>9022, :uris=>[\"ccng.cf.sandbox.wglabs.local\", \"api.cf.sandbox.wglabs.local\"], :tags=>{:component=>\"CloudController\"}}","log_level":"debug","source":"cf.registrar","data":{},"thread_id":19406520,"fiber_id":35479120,"process_id":8714,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.2.0/lib/cf/registrar.rb","lineno":95,"method":"send_registration_message"}

==> /var/vcap/sys/log/gorouter/gorouter.log <==
{"timestamp":1374019553.907715797,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.226 34567 [36c63a27e5590c7192d3b0c5e66d265a.cf.sandbox.wglabs.local] map[]  }","data":null}
{"timestamp":1374019553.910019398,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.203 9022 [ccng.cf.sandbox.wglabs.local api.cf.sandbox.wglabs.local] map[component:CloudController]  }","data":null}
{"timestamp":1374019554.923267603,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.201 8080 [login.cf.sandbox.wglabs.local] map[component:login]  }","data":null}
{"timestamp":1374019555.776266813,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.202 8080 [uaa.cf.sandbox.wglabs.local] map[component:uaa]  }","data":null}

==> /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log <==
{"timestamp":1374019558.9102356,"message":"Sending registration: {:host=>\"192.168.151.203\", :port=>9022, :uris=>[\"ccng.cf.sandbox.wglabs.local\", \"api.cf.sandbox.wglabs.local\"], :tags=>{:component=>\"CloudController\"}}","log_level":"debug","source":"cf.registrar","data":{},"thread_id":19406520,"fiber_id":35479120,"process_id":8714,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.2.0/lib/cf/registrar.rb","lineno":95,"method":"send_registration_message"}

==> /var/vcap/sys/log/gorouter/gorouter.log <==
{"timestamp":1374019558.911655426,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.203 9022 [ccng.cf.sandbox.wglabs.local api.cf.sandbox.wglabs.local] map[component:CloudController]  }","data":null}
{"timestamp":1374019558.913145065,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.226 34567 [36c63a27e5590c7192d3b0c5e66d265a.cf.sandbox.wglabs.local] map[]  }","data":null}
{"timestamp":1374019559.055811405,"process_id":8782,"source":"router.global","log_level":"info","message":"Droplet is not stale; NOT pruning: 192.168.151.201:8080","data":null}
{"timestamp":1374019559.926742315,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.201 8080 [login.cf.sandbox.wglabs.local] map[component:login]  }","data":null}
{"timestamp":1374019560.781044722,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.202 8080 [uaa.cf.sandbox.wglabs.local] map[component:uaa]  }","data":null}

==> /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log <==
{"timestamp":1374019563.9145381,"message":"Sending registration: {:host=>\"192.168.151.203\", :port=>9022, :uris=>[\"ccng.cf.sandbox.wglabs.local\", \"api.cf.sandbox.wglabs.local\"], :tags=>{:component=>\"CloudController\"}}","log_level":"debug","source":"cf.registrar","data":{},"thread_id":19406520,"fiber_id":35479120,"process_id":8714,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.2.0/lib/cf/registrar.rb","lineno":95,"method":"send_registration_message"}

==> /var/vcap/sys/log/gorouter/gorouter.log <==
{"timestamp":1374019563.914687634,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.226 34567 [36c63a27e5590c7192d3b0c5e66d265a.cf.sandbox.wglabs.local] map[]  }","data":null}
{"timestamp":1374019563.917032242,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.203 9022 [ccng.cf.sandbox.wglabs.local api.cf.sandbox.wglabs.local] map[component:CloudController]  }","data":null}
{"timestamp":1374019564.927382231,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.201 8080 [login.cf.sandbox.wglabs.local] map[component:login]  }","data":null}
{"timestamp":1374019565.781723738,"process_id":8782,"source":"router.global","log_level":"info","message":"Got router.register: &{192.168.151.202 8080 [uaa.cf.sandbox.wglabs.local] map[component:uaa]  }","data":null}


Log Tail Snippet for UAA:

2013-07-17_00:10:39.75297 #[722] INFO: Heartbeat sent
2013-07-17_00:10:39.75366 #[722] DEBUG: Heartbeat delivered
2013-07-17_00:10:56.87786 #[722] INFO: Message: {"method"=>"ssh", "arguments"=>[                                                                                                                     "setup", {"user"=>"bosh_zrk00s5q7", "public_key"=>"MIGfMA0GCSqGSIb3DQEBAQUAA4GNA                                                                                                                     DCBiQKBgQDHFr+KICms+tuT1OXJwhCUmR2d\nKVy7psa8xzElSyzqx7oJyfJ1JZyOzToj9T5SfTIq396                                                                                                                     agbHJWVfYphNahvZ/7uMX\nqHxf+ZH9BL1gk9Y6kCnbM5R60gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9                                                                                                                     Qs0wBug\nspULZVNRxq7veq/fzwIDAQAB\n", "password"=>"qOhewuRzL/UvU"}], "reply_to"=                                                                                                                     >"director.691c863b-92af-4cde-9b4b-e46300c1ea81.b48cf012-d640-48e1-8994-3eb151f7                                                                                                                     f85a"}
2013-07-17_00:10:56.87809 #[722] INFO: Setting up ssh for user bosh_zrk00s5q7
2013-07-17_00:10:56.92456 start: Job is already running: ssh
2013-07-17_00:10:56.92838 #[722] INFO: started sshd 2013-07-17 00:10:56 +0000
2013-07-17_00:10:56.92839 #[722] INFO: reply_to: director.691c863b-92af-4cde-9b4                                                                                                                     b-e46300c1ea81.b48cf012-d640-48e1-8994-3eb151f7f85a: payload: {:value=>{"command                                                                                                                     "=>"setup", "status"=>"success", "ip"=>"192.168.151.202"}}
2013-07-17_00:11:39.81271 #[722] INFO: Heartbeat sent
2013-07-17_00:11:39.81341 #[722] DEBUG: Heartbeat delivered

==> /var/vcap/monit/monit.log <==
[UTC Jul 16 20:42:24] info     : monit: generated unique Monit id 06eaf14a2853cc                                                                                                                     fcf01f8d6ebbecfe16 and stored to '/root/.monit.id'
[UTC Jul 16 20:42:24] info     : Starting monit daemon with http interface at [1                                                                                                                     27.0.0.1:2822]
[UTC Jul 16 20:42:24] info     : Starting monit HTTP server at [127.0.0.1:2822]
[UTC Jul 16 20:42:24] info     : monit HTTP server started
[UTC Jul 16 20:42:24] info     : 'system_2fda561b-0a6d-4a72-89de-2589128f3cfa' M                                                                                                                     onit started
[UTC Jul 16 20:42:24] error    : Cannot open a connection to the mailserver '127                                                                                                                     .0.0.1:2825' -- Transport endpoint is not connected
[UTC Jul 16 20:42:24] error    : No mail servers are available
[UTC Jul 16 20:42:24] error    : Cannot open a connection to the mailserver '127                                                                                                                     .0.0.1:2825' -- Transport endpoint is not connected
[UTC Jul 16 20:42:24] error    : No mail servers are available
[UTC Jul 16 20:42:24] error    : Alert handler failed, retry scheduled for next                                                                                                                      cycle
[UTC Jul 16 20:44:32] info     : Reinitializing monit daemon
[UTC Jul 16 20:44:32] info     : Awakened by the SIGHUP signal
[UTC Jul 16 20:44:32] info     : Reinitializing monit - Control file '/var/vcap/                                                                                                                     bosh/etc/monitrc'
[UTC Jul 16 20:44:32] info     : Shutting down monit HTTP server
[UTC Jul 16 20:44:32] info     : monit HTTP server stopped
[UTC Jul 16 20:44:32] info     : Starting monit HTTP server at [127.0.0.1:2822]
[UTC Jul 16 20:44:32] info     : monit HTTP server started
[UTC Jul 16 20:44:32] info     : 'system_2fda561b-0a6d-4a72-89de-2589128f3cfa' M                                                                                                                     onit reloaded
[UTC Jul 16 20:44:38] info     : start service 'uaa' on user request
[UTC Jul 16 20:44:38] info     : Awakened by User defined signal 1
[UTC Jul 16 20:44:38] info     : 'uaa' start: /var/vcap/jobs/uaa/bin/uaa_ctl
[UTC Jul 16 20:44:38] info     : monit daemon at 1398 awakened
[UTC Jul 16 20:44:38] info     : start service 'uaa_vcap_registrar' on user requ                                                                                                                     est
[UTC Jul 16 20:44:38] info     : monit daemon at 1398 awakened
[UTC Jul 16 20:44:39] info     : 'uaa' start action done
[UTC Jul 16 20:44:39] info     : 'uaa_vcap_registrar' start: /var/vcap/jobs/uaa/                                                                                                                     bin/vcap_registrar_ctl
[UTC Jul 16 20:44:40] info     : 'uaa_vcap_registrar' start action done
[UTC Jul 16 20:44:40] info     : Awakened by User defined signal 1

==> /var/vcap/sys/log/uaa/uaa.log <==
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/resources/**'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/favicon.ico'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/info'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/password/**'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/healthz/**'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- FilterChainProxy: /healthz at position 1 of 1 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'org.springframework.security.web.DefaultSecurityFilterChain#4' processing request GET /healthz
[2013-07-17 00:11:49.433] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- FilterChainProxy: /healthz reached end of additional filter chain; proceeding with original chain
[2013-07-17 00:11:49.434] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing GET request for [/healthz]
[2013-07-17 00:11:49.434] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /healthz
[2013-07-17 00:11:49.434] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public java.lang.String org.cloudfoundry.identity.uaa.web.HealthzEndpoint.getHealthz() throws java.lang.Exception]
[2013-07-17 00:11:49.434] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- DispatcherServlet: Last-Modified value for [/healthz] is: -1
[2013-07-17 00:11:49.435] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- RequestResponseBodyMethodProcessor: Written [ok
] as "text/plain;charset=ISO-8859-1" using [org.springframework.http.converter.StringHttpMessageConverter@191be075]
[2013-07-17 00:11:49.435] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-07-17 00:11:49.435] uaa - 11460 [http-bio-8080-exec-8] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-07-17 00:11:49.443] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:11:49.443] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details order by client_id]
[2013-07-17 00:11:49.445] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcScimUserProvisioning: Filtering groups with SQL: sql: id is not null order by created asc, params: {}
[2013-07-17 00:11:49.445] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcScimUserProvisioning: complete sql: select id,version,created,lastModified,username,email,givenName,familyName,active,phoneNumber from users where id is not null order by created asc, params: {}
[2013-07-17 00:11:49.445] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:11:49.445] uaa - 11460 [http-bio-8080-exec-7] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select count(*) from users where id is not null ]

==> /var/vcap/sys/log/uaa/localhost_access.2013-07-17.log <==
192.168.151.201 - - [17/Jul/2013:00:11:49 +0000] "GET /healthz HTTP/1.1" 200 3
192.168.151.201 - - [17/Jul/2013:00:11:49 +0000] "GET /varz HTTP/1.1" 200 2863

==> /var/vcap/sys/log/uaa/uaa.log <==
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/resources/**'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/favicon.ico'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/info'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/password/**'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/healthz/**'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- FilterChainProxy: /healthz at position 1 of 1 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'org.springframework.security.web.DefaultSecurityFilterChain#4' processing request GET /healthz
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- FilterChainProxy: /healthz reached end of additional filter chain; proceeding with original chain
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing GET request for [/healthz]
[2013-07-17 00:12:19.434] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /healthz
[2013-07-17 00:12:19.435] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public java.lang.String org.cloudfoundry.identity.uaa.web.HealthzEndpoint.getHealthz() throws java.lang.Exception]
[2013-07-17 00:12:19.435] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- DispatcherServlet: Last-Modified value for [/healthz] is: -1
[2013-07-17 00:12:19.436] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- RequestResponseBodyMethodProcessor: Written [ok
] as "text/plain;charset=ISO-8859-1" using [org.springframework.http.converter.StringHttpMessageConverter@191be075]
[2013-07-17 00:12:19.436] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-07-17 00:12:19.436] uaa - 11460 [http-bio-8080-exec-10] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-07-17 00:12:19.440] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:12:19.440] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details order by client_id]
[2013-07-17 00:12:19.443] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcScimUserProvisioning: Filtering groups with SQL: sql: id is not null order by created asc, params: {}
[2013-07-17 00:12:19.443] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcScimUserProvisioning: complete sql: select id,version,created,lastModified,username,email,givenName,familyName,active,phoneNumber from users where id is not null order by created asc, params: {}
[2013-07-17 00:12:19.443] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:12:19.443] uaa - 11460 [http-bio-8080-exec-9] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select count(*) from users where id is not null ]

==> /var/vcap/sys/log/uaa/localhost_access.2013-07-17.log <==
192.168.151.201 - - [17/Jul/2013:00:12:19 +0000] "GET /healthz HTTP/1.1" 200 3
192.168.151.201 - - [17/Jul/2013:00:12:19 +0000] "GET /varz HTTP/1.1" 200 2863

==> /var/vcap/bosh/log/current <==
2013-07-17_00:12:39.86516 #[722] INFO: Heartbeat sent
2013-07-17_00:12:39.86585 #[722] DEBUG: Heartbeat delivered

==> /var/vcap/sys/log/uaa/uaa.log <==
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/resources/**'
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/favicon.ico'
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/info'
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/password/**'
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/healthz/**'
[2013-07-17 00:12:49.478] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- FilterChainProxy: /healthz at position 1 of 1 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'org.springframework.security.web.DefaultSecurityFilterChain#4' processing request GET /healthz
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- FilterChainProxy: /healthz reached end of additional filter chain; proceeding with original chain
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing GET request for [/healthz]
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /healthz
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public java.lang.String org.cloudfoundry.identity.uaa.web.HealthzEndpoint.getHealthz() throws java.lang.Exception]
[2013-07-17 00:12:49.479] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- DispatcherServlet: Last-Modified value for [/healthz] is: -1
[2013-07-17 00:12:49.481] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- RequestResponseBodyMethodProcessor: Written [ok
] as "text/plain;charset=ISO-8859-1" using [org.springframework.http.converter.StringHttpMessageConverter@191be075]
[2013-07-17 00:12:49.481] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-07-17 00:12:49.481] uaa - 11460 [http-bio-8080-exec-1] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-07-17 00:12:49.491] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:12:49.491] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details order by client_id]
[2013-07-17 00:12:49.493] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcScimUserProvisioning: Filtering groups with SQL: sql: id is not null order by created asc, params: {}
[2013-07-17 00:12:49.493] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcScimUserProvisioning: complete sql: select id,version,created,lastModified,username,email,givenName,familyName,active,phoneNumber from users where id is not null order by created asc, params: {}
[2013-07-17 00:12:49.493] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:12:49.493] uaa - 11460 [http-bio-8080-exec-2] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select count(*) from users where id is not null ]

==> /var/vcap/sys/log/uaa/localhost_access.2013-07-17.log <==
192.168.151.201 - - [17/Jul/2013:00:12:49 +0000] "GET /healthz HTTP/1.1" 200 3
192.168.151.201 - - [17/Jul/2013:00:12:49 +0000] "GET /varz HTTP/1.1" 200 2863
192.168.151.201 - - [17/Jul/2013:00:13:19 +0000] "GET /healthz HTTP/1.1" 200 3
192.168.151.201 - - [17/Jul/2013:00:13:19 +0000] "GET /varz HTTP/1.1" 200 2863

==> /var/vcap/sys/log/uaa/uaa.log <==
[2013-07-17 00:13:19.533] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/resources/**'
[2013-07-17 00:13:19.533] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/favicon.ico'
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/info'
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/password/**'
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/healthz'; against '/healthz/**'
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- FilterChainProxy: /healthz at position 1 of 1 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'org.springframework.security.web.DefaultSecurityFilterChain#4' processing request GET /healthz
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- FilterChainProxy: /healthz reached end of additional filter chain; proceeding with original chain
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing GET request for [/healthz]
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /healthz
[2013-07-17 00:13:19.534] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public java.lang.String org.cloudfoundry.identity.uaa.web.HealthzEndpoint.getHealthz() throws java.lang.Exception]
[2013-07-17 00:13:19.535] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- DispatcherServlet: Last-Modified value for [/healthz] is: -1
[2013-07-17 00:13:19.535] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- RequestResponseBodyMethodProcessor: Written [ok
] as "text/plain;charset=ISO-8859-1" using [org.springframework.http.converter.StringHttpMessageConverter@191be075]
[2013-07-17 00:13:19.536] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-07-17 00:13:19.536] uaa - 11460 [http-bio-8080-exec-3] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-07-17 00:13:19.540] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:13:19.540] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details order by client_id]
[2013-07-17 00:13:19.542] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcScimUserProvisioning: Filtering groups with SQL: sql: id is not null order by created asc, params: {}
[2013-07-17 00:13:19.542] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcScimUserProvisioning: complete sql: select id,version,created,lastModified,username,email,givenName,familyName,active,phoneNumber from users where id is not null order by created asc, params: {}
[2013-07-17 00:13:19.542] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-07-17 00:13:19.542] uaa - 11460 [http-bio-8080-exec-4] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select count(*) from users where id is not null ]




My current manifest:

    - 192.168.151.2 - 192.168.151.199

    - 192.168.151.251 - 192.168.151.254 #reserved for lb BW
    static:

    - 192.168.151.200 - 192.168.151.220 #this leaves 220-250 open for synamic vms

     
  - name: medium
    network: default
    size: 3

    stemcell:
      name: bosh-stemcell
      version: 1.5.0.pre2
    cloud_properties:
      ram: 4096
      disk: 8192
      cpu: 1



jobs:
  - name: data
    template:
      - postgres
      - debian_nfs_server
    instances: 1

    resource_pool: medium
    persistent_disk: 16384
    networks:
      - name: default
        default: [dns, gateway]
        static_ips:

          - 192.168.151.200
    properties:
      db: databases
     
  - name: core
    template:
      - syslog_aggregator
      - nats
      - health_manager_next
      - collector
      - login
    instances: 1
    resource_pool: medium #??
    persistent_disk: 16384 #??

    networks:
      - name: default
        default: [dns, gateway]
        static_ips:
          - 192.168.151.201

    properties: #??
      db: databases
      cc_props: cc
      hm_props: health_manager_ccng


  - name: uaa
    template:

    address: 192.168.151.200

    #network: "*.cf.microbosh"
    #idmapd_domain: iad1


  debian_nfs_server:
    no_root_squash: true


  databases: &databases
    db_scheme:
postgres
    address: 192.168.151.200

    port: 5524
    roles:
      - tag: admin
        name: ccadmin
        password: "c1oudc0w"
      - tag: admin
        name: uaaadmin
        password: "c1oudc0w"
    databases:
      - tag: cc
        name: ccdb
        citext: true
      - tag: uaa
        name: uaadb
        citext: true


  ccdb: &ccdb
    db_scheme:
postgres
    address: 192.168.151.200

    port: 5524
    roles:
      - tag: admin
        name: ccadmin
        password: "c1oudc0w"
    databases:
      - tag: cc
        name: ccdb
        citext: true


  ccdb_ng: *ccdb


  uaadb:
    db_scheme:
postgresql
    address: 192.168.151.200

Dr Nic Williams

unread,
Jul 16, 2013, 8:28:01 PM7/16/13
to bosh-users
It says you're using stemcell 1.5.0.pre2. I think the latest stemcell from source (via rake task) should say 1.5.0.pre3; and 1.5.0.pre8XY if you get it from the s3 bucket. BUT, it doesn't seem that this is related to the issue. Perhaps create a modern stemcell as a last resort.

The core job won't need a persistent disk (it references the DB & nfs for storage)

The two job logs don't infer any issues. BUT, I don't see any traffic coming in from your cf CLI.

Can you dump out ~/.cf/crash? Perhaps your CLI doesn't have network access or DNS isn't mapped to 192.168.151.251?

Nic


Barry Williams

unread,
Jul 16, 2013, 8:37:06 PM7/16/13
to bosh-...@cloudfoundry.org
Here you go

wglabs@ubuntu:~/deployments$ cf target
Target Information (where will apps be pushed):
  CF instance: http://api.cf.sandbox.wglabs.local (API version: 2)
  user: N/A
  target app space: N/A (org: N/A)
wglabs@ubuntu:~/deployments$ cf login admin

CF::UAA::BadTarget: error: Connection refused - connect(2)
cat ~/.cf/crash # for more details
wglabs@ubuntu:~/deployments$ cat ~/.cf/crash
Time of crash:
  2013-07-16 20:35:46 -0400

CF::UAA::BadTarget: error: Connection refused - connect(2)

cf-uaa-lib-1.3.10/lib/uaa/http.rb:161:in `rescue in net_http_request'
cf-uaa-lib-1.3.10/lib/uaa/http.rb:141:in `net_http_request'
cf-uaa-lib-1.3.10/lib/uaa/http.rb:129:in `request'
cf-uaa-lib-1.3.10/lib/uaa/http.rb:111:in `http_get'
cf-uaa-lib-1.3.10/lib/uaa/http.rb:81:in `json_get'
cf-uaa-lib-1.3.10/lib/uaa/misc.rb:58:in `server'
cfoundry-2.4.0/lib/cfoundry/uaaclient.rb:16:in `block in prompts'
cfoundry-2.4.0/lib/cfoundry/uaaclient.rb:128:in `wrap_uaa_errors'
cfoundry-2.4.0/lib/cfoundry/uaaclient.rb:15:in `prompts'
cfoundry-2.4.0/lib/cfoundry/concerns/login_helpers.rb:6:in `login_prompts'
cf-4.2.1/lib/cf/cli/start/login.rb:35:in `login'
mothership-0.5.1/lib/mothership/base.rb:66:in `run'
mothership-0.5.1/lib/mothership/command.rb:72:in `block in invoke'
mothership-0.5.1/lib/mothership/command.rb:86:in `instance_exec'
mothership-0.5.1/lib/mothership/command.rb:86:in `invoke'
mothership-0.5.1/lib/mothership/base.rb:55:in `execute'
cf-4.2.1/lib/cf/cli.rb:190:in `block (2 levels) in execute'
cf-4.2.1/lib/cf/cli.rb:197:in `save_token_if_it_changes'
cf-4.2.1/lib/cf/cli.rb:189:in `block in execute'
cf-4.2.1/lib/cf/cli.rb:125:in `wrap_errors'
cf-4.2.1/lib/cf/cli.rb:185:in `execute'
mothership-0.5.1/lib/mothership.rb:45:in `start'
cf-4.2.1/bin/cf:13:in `<top (required)>'
ruby-1.9.3-p327/bin/cf:19:in `load'
ruby-1.9.3-p327/bin/cf:19:in `<main>'
ruby-1.9.3-p327/bin/ruby_noexec_wrapper:14:in `eval'
ruby-1.9.3-p327/bin/ruby_noexec_wrapper:14:in `<main>'

Dr Nic Williams

unread,
Jul 16, 2013, 8:40:08 PM7/16/13
to bosh-users
Access to cloud controller & uaa is via the gorouter. So something should show up in the gorouter logs (I think) when you attempt to login.

My guess is that http://api.cf.sandbox.wglabs.local either does not map to the gorouter VM's IP; or you don't have access to that IP from your terminate.

The dig command might help diagnose whether DNS translation is to the correct IP (or setup at all).

Nic

Barry Williams

unread,
Jul 16, 2013, 8:41:46 PM7/16/13
to bosh-...@cloudfoundry.org
There is also this output from http on api.  Didn't know if it would help.

wglabs@ubuntu:~/deployments$ curl  http://api.cf.sandbox.wglabs.local/
{"code":10000,"description":"Unknown request"}

wglabs@ubuntu:~/deployments$ curl  http://api.cf.sandbox.wglabs.local/info
{"name":"vcap","build":"2222","support":"http://support.cloudfoundry.com","version":2,"description":"Cloud Foundry sponsored by Pivotal","authorization_endpoint":"http://login.cf.sandbox.wglabs.local","token_endpoint":"http://uaa.cf.sandbox.wglabs.local","allow_debug":true}

Dr Nic Williams

unread,
Jul 16, 2013, 8:43:50 PM7/16/13
to bosh-users
This is good news then :)

I notice the .local domain. Is this visible to the VMs too? If you ssh into the gorouter VM, can you still run: curl  http://api.cf.sandbox.wglabs.local/info ?

Barry Williams

unread,
Jul 16, 2013, 9:00:18 PM7/16/13
to bosh-...@cloudfoundry.org
Yes and Yes.  I was able to log into the gorouter vm (which is actually "api"), and I did the curl http://api.cf...  and it got the proper response.

Should I separate gorouter and ccng?

Here are my DNS settings for reference:
all under cf.sandbox.wglabs.local
192.168.151.201 - console
192.168.151.202 - uaa, login, support-signon, servicesmgmt
192.168.151.251 - api

I made the dns entries based on names in the manifest.

Dr Nic Williams

unread,
Jul 16, 2013, 9:03:56 PM7/16/13
to bosh-...@cloudfoundry.org
For the moment I've run out of useful debugging ideas.

Ferdy?
--
Dr Nic Williams
Stark & Wayne LLC - the consultancy for Cloud Foundry
http://starkandwayne.com
+1 415 860 2185
twitter: drnic

Barry Williams

unread,
Jul 18, 2013, 3:08:16 PM7/18/13
to bosh-...@cloudfoundry.org
Just wanted to let you know that I was able to get it working.
It was the entries in my DNS, they were all pointing to the actual machine for the service, instead of all pointing to the router.

So, now that it is pointing to the right spot, it seems to be working well.
Although, I noticed that console gives me a 404 error.  Perhaps some job I need to add?

Anyways,
Thank you so much for you help, Nic.

Barry

Dr Nic Williams

unread,
Jul 18, 2013, 3:21:35 PM7/18/13
to bosh-...@cloudfoundry.org, bosh-...@cloudfoundry.org
It was the DNS!! Hurray for networking issues :)

What console are you referring to?
--
Dr Nic Williams
Stark & Wayne LLC - the consultancy for Cloud Foundry
http://starkandwayne.com
+1 415 860 2185
twitter: drnic


tackr...@gmail.com

unread,
Jul 18, 2013, 5:47:26 PM7/18/13
to bosh-...@cloudfoundry.org
Hey Nic...I work with Barry and wanted to reply back.

We can get to the login page (http://login.cf.sandbox.wglabs.local), and more importantly we can now successfully log in with admin/c1oudc0w.  After logging in, we get to the welcome page with links for Cloud Foundry console, account settings, and logout.  The Account Settings link works, but the Cloud Foundry console does not.  It takes us to http://console.cf.sandbox.wglabs.local and immediately give us a 404 Not Found error. Also, on the login page, the link for Forgot Password (http://console.cf.sandbox.wglabs.local/password_resets/new) and Create Account (http://console.cf.sandbox.wglabs.local/register) do the same thing.  It's as if either that URL is pointing to the wrong thing or there's some dependent component not configured right or missing.  Note, "console" is pointing to the IP of gorouter, just like api, uaa, and login.

It's also worth noting that the cf command-line command seems to be fully-functional.  We can target, login, and manage users, orgs, and spaces.  Haven't tried to push an app yet, but let's assume that's working, too.

Any ideas?  I'm sure it's something simple, but we can't put our finger on it.

Side note...is it odd that the 3 folks on this thread are all Williams? :)

Ferran Rodenas

unread,
Jul 18, 2013, 6:12:46 PM7/18/13
to bosh-...@cloudfoundry.org
I'm not Williams, so not sure If I'm allowed to answer your question ;) Anyway, console is not part of the oss bits, it's part of a future enterprise release, that's the reason why the console is not deployed.

- Ferdy


2013/7/18 <tackr...@gmail.com>

David Williams

unread,
Jul 18, 2013, 9:51:24 PM7/18/13
to bosh-...@cloudfoundry.org
OK, gotcha...thanks, Ferdy!  Sounds like Cloud Foundry is truly Pivotal now. :)

Thank you both for your help!
Reply all
Reply to author
Forward
0 new messages