ZAPI-721: HTTP API non-functional while changefeed and other aspects still working

Resolution

Fixed: A fix for this issue is checked into the tree and tested.
(Resolution Date: 2016-01-23T01:48:59.000Z)

Fix Versions

2016-02-04 Hurricane Karen (Release Date: 2016-04-02)

Description

@trent.mick's CoaL deployment resulted in VMAPI being up, but not responsive to the HTTP API. Logs suggest that changefeed and the moray clients are still working, but for whatever reason the HTTP API was unresponsive. Looking at the logs shows that changefeed did backoff due to moray unavailability, but succeeded on the next attempt to create the bucket. Subsequent logs also point towards changefeed working as well as the general VMAPI moray client.

At this point I suspect that either changefeed's 'moray-ready' event was not emitted or VMAPI's 'moray-ready' or 'ready' events were not emitted to signal the bootstrapping of restify routes.

I deployed a brand new CoaL, but was unable to reproduce the issue. Below is the head of @trent.mick's CoaL VMAPI log.

[ Jan 19 18:50:11 Enabled. ]
[ Jan 19 18:50:11 Rereading configuration. ]
[ Jan 19 18:50:11 Executing start method ("/opt/smartdc/vmapi/build/node/bin/node --abort_on_uncaught_exception /opt/smartdc/vmapi/server.js &"). ]
[ Jan 19 18:50:11 Method "start" exited with status 0. ]
[2016-01-19T18:50:12.695Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: checking moray.coal.joyent.us in DNS (host=moray.coal.joyent.us, port=2020)
[2016-01-19T18:50:12.929Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Loading the WFAPI workflows...
[2016-01-19T18:50:12.961Z] DEBUG: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: resolve moray.coal.joyent.us done after 1 attempts (domain=moray.coal.joyent.us)
[2016-01-19T18:50:12.981Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: host online (host=10.99.99.17, port=2020)
[2016-01-19T18:50:12.981Z]  INFO: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: cf: moray: connected (moray="[object MorayClient<host=moray.coal.joyent.us>]")
[2016-01-19T18:50:12.982Z]  WARN: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Backing off -- retry count: 0 delay: 10
[2016-01-19T18:50:12.987Z]  INFO: moray/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: moray: connected (moray="[object MorayClient<host=moray.coal.joyent.us>]")
[2016-01-19T18:50:13.000Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: getBucket: entered (req_id=7975677a-d3aa-c2dc-e184-b41bf2815ae0, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-0, bucket=vmapi_changefeed)
[2016-01-19T18:50:13.027Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: getBucket: failed (req_id=7975677a-d3aa-c2dc-e184-b41bf2815ae0, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-0)
    BucketNotFoundError: vmapi_changefeed does not exist
        at EventEmitter.<anonymous> (/opt/smartdc/moray/lib/buckets/get.js:56:16)
        at EventEmitter.g (events.js:180:16)
        at EventEmitter.emit (events.js:95:17)
        at endOrError (/opt/smartdc/moray/lib/pg.js:97:13)
        at f (/opt/smartdc/moray/node_modules/once/once.js:16:25)
        at onQueryEnd (/opt/smartdc/moray/lib/pg.js:124:9)
        at EventEmitter.emit (events.js:95:17)
        at Query.handleReadyForQuery (/opt/smartdc/moray/node_modules/pg/lib/query.js:86:8)
        at null.<anonymous> (/opt/smartdc/moray/node_modules/pg/lib/client.js:159:19)
        at EventEmitter.emit (events.js:117:20)
[2016-01-19T18:50:13.028Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: createBucket: entered (req_id=fcd7409e-ec5b-c487-f0de-867341d31f9c, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-1, bucket=vmapi_changefeed)
    config: {
      "index": {
        "published": {
          "type": "string"
        }
      },
      "pre": [],
      "post": []
    }
[2016-01-19T18:50:13.028Z] ERROR: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Bucket was not loaded
    BucketNotFoundError: vmapi_changefeed does not exist
        at EventEmitter.<anonymous> (/opt/smartdc/moray/lib/buckets/get.js:56:16)
        at EventEmitter.g (events.js:180:16)
        at EventEmitter.emit (events.js:95:17)
        at endOrError (/opt/smartdc/moray/lib/pg.js:97:13)
        at f (/opt/smartdc/moray/node_modules/once/once.js:16:25)
        at onQueryEnd (/opt/smartdc/moray/lib/pg.js:124:9)
        at EventEmitter.emit (events.js:95:17)
        at Query.handleReadyForQuery (/opt/smartdc/moray/node_modules/pg/lib/query.js:86:8)
        at null.<anonymous> (/opt/smartdc/moray/node_modules/pg/lib/client.js:159:19)
        at EventEmitter.emit (events.js:117:20)
[2016-01-19T18:50:13.081Z]  INFO: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Connected to Workflow API
[2016-01-19T18:50:13.092Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: createBucket done (req_id=fcd7409e-ec5b-c487-f0de-867341d31f9c, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-1)
[2016-01-19T18:50:13.093Z]  INFO: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Bucket successfully loaded
[2016-01-19T18:50:13.096Z]  INFO: vmapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: VMAPI listening (url=http://0.0.0.0:80)
[2016-01-19T18:50:13.096Z]  INFO: vmapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: All services are up
[2016-01-19T18:50:13.125Z]  INFO: moray/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: Buckets have been loaded
[2016-01-19T18:50:14.021Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: provision-7.3.0 workflow added
[2016-01-19T18:50:14.046Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: start-7.0.6 workflow added
[2016-01-19T18:50:14.077Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: stop-7.0.7 workflow added
[2016-01-19T18:50:14.102Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: kill-7.0.1 workflow added
[2016-01-19T18:50:14.150Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: reboot-7.0.5 workflow added
[2016-01-19T18:50:14.174Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: reprovision-7.0.3 workflow added
[2016-01-19T18:50:14.201Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: update-7.1.8 workflow added
[2016-01-19T18:50:14.232Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: destroy-7.1.0 workflow added
[2016-01-19T18:50:14.254Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: snapshot-7.0.3 workflow added
[2016-01-19T18:50:14.285Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: rollback-7.0.4 workflow added
[2016-01-19T18:50:14.306Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: delete-snapshot-7.0.3 workflow added
[2016-01-19T18:50:14.347Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: add-nics-7.0.10 workflow added
[2016-01-19T18:50:14.380Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: update-nics-7.0.3 workflow added
[2016-01-19T18:50:14.438Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: remove-nics-7.0.5 workflow added
[2016-01-19T18:50:14.438Z] DEBUG: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: wfapi: connected after 1 attempts
[2016-01-19T18:50:14.438Z]  INFO: vmapi/wfapi/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: All workflows have been loaded
[2016-01-19T18:50:14.945Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: findObjects: entered (req_id=ce59195e-1db1-6c81-89d1-8b03ea914ee0, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-2, bucket=vmapi_changefeed, filter=(published=no))
    options: {
      "req_id": "ce59195e-1db1-6c81-89d1-8b03ea914ee0",
      "headers": {},
      "no_count": false,
      "sql_only": false,
      "noCache": true
    }
[2016-01-19T18:50:14.951Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: findObjects: done (req_id=ce59195e-1db1-6c81-89d1-8b03ea914ee0, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-2)
[2016-01-19T18:50:14.951Z]  INFO: vmapi/changefeed/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: findObjects ended
[2016-01-19T18:50:16.971Z] DEBUG: vmapi/MorayClient/27336 on e03beccf-101a-499a-81af-41e5129a1e0f: findObjects: entered (req_id=3e5b5b7b-f30a-e62b-9a73-cd78301ac568, host=moray.coal.joyent.us, port=2020, fastClient=10.99.99.17-3, bucket=vmapi_changefeed, filter=(published=no))
    options: {
      "req_id": "3e5b5b7b-f30a-e62b-9a73-cd78301ac568",
      "headers": {},
      "no_count": false,
      "sql_only": false,
      "noCache": true
    }

Comments

Comment by Trent Mick
Created at 2016-01-20T16:59:51.000Z
Hit this again on my coal boot this morning.

Symptoms:

[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# curl -v localhost/ping
*   Trying ::1...
* Failed to set TCP_KEEPALIVE on fd 4
* Connection failed
* connect to ::1 port 80 failed: Connection refused
*   Trying 127.0.0.1...
* Failed to set TCP_KEEPALIVE on fd 5
* Immediate connect fail for 127.0.0.1: Connection refused
*   Trying 127.0.0.1...
* Failed to set TCP_KEEPALIVE on fd 4
* Connection failed
* connect to 127.0.0.1 port 80 failed: Connection refused
* Failed to connect to localhost port 80: Connection refused
* Closing connection 0
curl: (7) Failed to connect to localhost port 80: Connection refused
[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# curl -v 10.99.99.27/ping
*   Trying 10.99.99.27...
* Failed to set TCP_KEEPALIVE on fd 3
* Connection failed
* connect to 10.99.99.27 port 80 failed: Connection refused
* Failed to connect to 10.99.99.27 port 80: Connection refused
* Closing connection 0
curl: (7) Failed to connect to 10.99.99.27 port 80: Connection refused
[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# netstat

TCP: IPv4
   Local Address        Remote Address    Swind Send-Q Rwind Recv-Q    State
-------------------- -------------------- ----- ------ ----- ------ -----------
10.99.99.27.33154    10.99.99.11.2181     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.54689    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.46936    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.43107    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.55954    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.46558    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.38248    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.35965    10.99.99.19.80       1049792      0 1049800      0 ESTABLISHED
10.99.99.27.40278    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.63676    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.58753    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.32772    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.64698    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.52486    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.50639    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.46863    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.33668    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.41676    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.62801    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.47394    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.46412    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.57605    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
warning: /opt/local/bin/eqn should have been given a `-Tascii' option
10.99.99.27.63544    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.43065    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.63017    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.43720    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.61491    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED
10.99.99.27.36016    10.99.99.17.2020     1049792      0 1049800      0 ESTABLISHED

Active UNIX domain sockets
Address  Type          Vnode     Conn  Local Addr      Remote Addr
ffffff02a61d4be8 stream-ord 00000000     00000000
ffffff02849a5460 stream-ord 00000000     00000000
ffffff02849a5820 stream-ord 00000000     00000000
ffffff0283af3810 stream-ord 00000000     00000000
ffffff027df367e8 stream-ord 00000000     00000000
ffffff027df3d420 stream-ord 00000000     00000000
ffffff027df407d8 stream-ord 00000000     00000000
ffffff027f640048 stream-ord 00000000     00000000
ffffff028072f3f8 stream-ord 00000000     00000000
ffffff02802f13e8 stream-ord 00000000     00000000
ffffff02800c0018 stream-ord 00000000     00000000
ffffff027a587008 stream-ord 00000000     00000000
ffffff027a5913c0 stream-ord 00000000     00000000
ffffff0277d310f0 stream-ord ffffff0271c67b40 00000000    /.zonecontrol/metadata.sock
ffffff0277d314b0 stream-ord 00000000     00000000
ffffff0277d31870 stream-ord 00000000     00000000
ffffff02785570e8 stream-ord 00000000     00000000
ffffff0277974858 stream-ord 00000000     00000000
ffffff027458a0b0 stream-ord 00000000     00000000
ffffff0274096468 stream-ord 00000000     00000000
ffffff0273f350a0 stream-ord 00000000     00000000
ffffff0273f35460 stream-ord 00000000     00000000
ffffff027428e090 stream-ord 00000000     00000000
ffffff027428ebd0 stream-ord 00000000     00000000
ffffff0273663440 stream-ord 00000000     00000000
ffffff0273663bc0 stream-ord 00000000     00000000
ffffff0271b42bb0 stream-ord 00000000     00000000
ffffff0271b4c068 stream-ord ffffff031a632340 00000000    /var/run/.smartdc-amon.sock
ffffff02700e17c0 stream-ord 00000000     00000000
ffffff02700b77b0 stream-ord 00000000     00000000
ffffff02700b7b70 stream-ord 00000000     00000000
ffffff026f3d73e0 stream-ord 00000000     00000000

Uploaded gcore of vmapi process:

[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# svcs -p vmapi
STATE          STIME    FMRI
online         16:30:18 svc:/smartdc/site/vmapi:default
               16:30:04    12403 node
[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# pargs 12403
12403:  /opt/smartdc/vmapi/build/node/bin/node --abort_on_uncaught_exception /opt/smart
argv[0]: /opt/smartdc/vmapi/build/node/bin/node
argv[1]: --abort_on_uncaught_exception
argv[2]: /opt/smartdc/vmapi/server.js
[root@e03beccf-101a-499a-81af-41e5129a1e0f (coal:vmapi0) ~]# ptree 12403
6876  zsched
  7041  /sbin/init
    12403 /opt/smartdc/vmapi/build/node/bin/node --abort_on_uncaught_exception /opt/sm


$ thoth upload core.12403
thoth: using database at 165.225.169.30:28015 (configured from Manta)
thoth: creating 2dd3aa5c541a386a6596a4812b032df0
thoth: uploading core.12403 to 2dd3aa5c541a386a6596a4812b032df0
thoth: core.12403     [=============================>] 100%  73.94MB 310.25KB/s  4m 4s
thoth: creating job to uncompress 2dd3aa5c541a386a6596a4812b032df0
thoth: adding key to job 295bfc16-2b39-e76b-91b0-d09265b2bc09
thoth: processing job 295bfc16-2b39-e76b-91b0-d09265b2bc09
thoth: waiting for completion of job 295bfc16-2b39-e76b-91b0-d09265b2bc09
thoth: job 295bfc16-2b39-e76b-91b0-d09265b2bc09 completed in 0h0m7s
thoth: creating job to process 2dd3aa5c541a386a6596a4812b032df0
thoth: adding key to job 3ddaed26-b7a6-c939-8ad9-ed538f38ca4b
thoth: processing 2dd3aa5c541a386a6596a4812b032df0
thoth: waiting for completion of job 3ddaed26-b7a6-c939-8ad9-ed538f38ca4b
thoth: job 3ddaed26-b7a6-c939-8ad9-ed538f38ca4b completed in 0h0m2s

After a 'svcadm restart vmapi' it was fine.

Comment by Trent Mick
Created at 2016-01-20T17:09:02.000Z
Thoth aside: I failed attempting to "ticket" this dump:

$ thoth ticket 2dd3aa5c541a386a6596a4812b032df0 ZAPI-721
thoth: using database at 165.225.169.30:28015 (configured from Manta)
thoth: adding key to job e34dbdc6-6fc3-4301-fe52-f7fc45d1ee14
thoth: processing job e34dbdc6-6fc3-4301-fe52-f7fc45d1ee14
thoth: waiting for completion of job e34dbdc6-6fc3-4301-fe52-f7fc45d1ee14
thoth: job e34dbdc6-6fc3-4301-fe52-f7fc45d1ee14 failed: { id: 'e34dbdc6-6fc3-4301-fe52-f7fc45d1ee14',
  name: '',
  state: 'done',
  cancelled: false,
  inputDone: true,
  transient: false,
  stats: { errors: 1, outputs: 0, retries: 0, tasks: 0, tasksDone: 0 },
  timeCreated: '2016-01-20T17:08:12.968Z',
  timeDone: '2016-01-20T17:08:13.388Z',
  timeArchiveStarted: '2016-01-20T17:08:13.529Z',
  phases:
   [ { exec: 'cat > /tmp/tmp.json <<EOF\n{ "ticket": "ZAPI-721"} \nEOF\ncat $MANTA_INPUT_FILE /tmp/tmp.json | json --deep-merge > /tmp/new.json;mput -f /tmp/new.json $MANTA_INPUT_OBJECT ;/opt/custom/thoth/node_modules/manta-thoth/bin/thoth load /tmp/new.json || mln $MANTA_INPUT_OBJECT /thoth/stor/thoth/`basename $(dirname $MANTA_INPUT_OBJECT)`-unindexed.json',
       type: 'map',
       assets: [Object],
       init: 'echo \'{"db": {"host":"165.225.169.30","port":28015,"db":"thoth","authKey":"doogle","table":"dumps"}}\' > ~/.thoth.config.json; cd / ; tar xzf /assets//thoth/public/assets/thoth.tar.gz' } ],
  options: {} }
[09:08:13 trentm@danger0:~]
$ echo $?
1

Comment by Richard Kiene
Created at 2016-01-20T23:46:47.000Z
I'm not finding anything in @trent.mick's core yet, and I've been unable to reproduce the issue with my own coal deployments. I've uploaded a core from my working VMAPI to try and do some property/closure diffing. My core is in thoth with id 9bd68eb5f10ec8b36e5a27602237ab35.

Comment by Richard Kiene
Created at 2016-01-20T23:57:37.000Z
Interestingly enough, in both of the logs that I was provided, VMAPI thinks everything is okay, as indicated by the presence of "All services are up" which is only triggered after changefeed and VMAPI have established a connection with Moray and setup all the route handling.

Comment by Richard Kiene
Created at 2016-01-21T00:34:59.000Z
The only meaningful error messages I can get from the logs are related to wfapi:

./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.838Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.839Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.840Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.840Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.841Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"vmapi","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"component":"wfapi","level":50,"error":{"message":"Backend not connected","statusCode":503,"body":{"code":"ServiceUnavailableError","message":"Backend not connected"},"restCode":"ServiceUnavailableError","name":"ServiceUnavailableError"},"msg":"Ping failed","time":"2016-01-19T19:12:23.841Z","v":0}
./vmapi_e03beccf-101a-499a-81af-41e5129a1e0f_2016-01-19T20:00:00.log:{"name":"moray","hostname":"e03beccf-101a-499a-81af-41e5129a1e0f","pid":14450,"level":50,"err":{"message":"the database system is starting up","name":"error","stack":"error: the database system is starting up\n    at Connection.parseE (/opt/smartdc/moray/node_modules/pg/lib/connection.js:561:11)\n    at Connection.parseMessage (/opt/smartdc/moray/node_modules/pg/lib/connection.js:390:17)\n    at null.<anonymous> (/opt/smartdc/moray/node_modules/pg/lib/connection.js:92:20)\n    at Socket.EventEmitter.emit (events.js:95:17)\n    at Socket.<anonymous> (_stream_readable.js:746:14)\n    at Socket.EventEmitter.emit (events.js:92:17)\n    at emitReadable_ (_stream_readable.js:408:10)\n    at emitReadable (_stream_readable.js:404:5)\n    at readableAddChunk (_stream_readable.js:165:9)\n    at Socket.Readable.push (_stream_readable.js:127:10)"},"msg":"Buckets were not loaded","time":"2016-01-19T19:12:24.569Z","v":0}

And it appears related to a Moray / Manatee unavailability issue.

Comment by Bot Bot [X]
Created at 2016-01-23T01:37:46.000Z

node-sdc-changefeed commit 24fdb0f (branch master, by Richard Kiene)

ZAPI-721: Remove double callback and backoff race


Comment by Bot Bot [X]
Created at 2016-01-23T01:45:50.000Z

sdc-vmapi commit 216fde6 (branch master, by Richard Kiene)

ZAPI-721: Don't call publisher start until moray is ready


Comment by Richard Kiene
Created at 2016-01-23T01:48:59.000Z
@trent.mick and @orlando thank you for the gcore and logs!