ZAPI-744: nightly-setup failure due to VMAPI crash due to subtle behaviour change in restify 4.x

Resolution

Fixed: A fix for this issue is checked into the tree and tested.
(Resolution Date: 2016-10-28T02:06:15.000Z)

Fix Versions

2016-11-10 CANADIAN THRUST (Release Date: 2016-11-10)

Description

nightly-setup failure: https://jenkins.joyent.us/view/nightly/job/nightly1-010-setup/820/console

[2016-07-11T08:11:37Z] :59: setup_docker(): ADMIN_UUID=930896af-bf8c-48d4-885c-6573a94b1853
[2016-07-11T08:11:37Z] :60: setup_docker(): local NUM_ZONES
[[2016-07-11T08:11:37Z] :61: setup_docker(): json -H length
[[2016-07-11T08:11:37Z] :61: setup_docker(): sdc-vmapi '/vms?state=active&owner_uuid=930896af-bf8c-48d4-885c-6573a94b1853&tag.smartdc_role=docker'
curl: (52) Empty reply from server
[2016-07-11T08:11:38Z] :61: setup_docker(): NUM_ZONES=
[2016-07-11T08:11:38Z] bin/stage-setup:1: errexit 52

this was a VMAPI crash:

[root@headnode (nightly-1) ~]# sdc-vmapi '/vms?state=active&owner_uuid=930896af-bf8c-48d4-885c-6573a94b1853&tag.smartdc_role=docker'

# leads to:
Uncaught TypeError: Cannot convert object to primitive value

FROM
Object.tag (/opt/smartdc/vmapi/lib/common/validation.js:717:41)
validate (/opt/smartdc/vmapi/lib/common/validation.js:2375:52)
validateParams (/opt/smartdc/vmapi/lib/common/validation.js:2374:35)
validateSingleParams (/opt/smartdc/vmapi/lib/common/validation.js:1442:20)
/opt/smartdc/vmapi/node_modules/async/lib/async.js:542:21
/opt/smartdc/vmapi/node_modules/async/lib/async.js:222:13
iterate (/opt/smartdc/vmapi/node_modules/async/lib/async.js:123:13)
async.eachSeries (/opt/smartdc/vmapi/node_modules/async/lib/async.js:145:9)
_asyncMap (/opt/smartdc/vmapi/node_modules/async/lib/async.js:221:9)
Object.mapSeries (/opt/smartdc/vmapi/node_modules/async/lib/async.js:211:23)
Object.async.series (/opt/smartdc/vmapi/node_modules/async/lib/async.js:540:19)
Object.validateListVmsParams (/opt/smartdc/vmapi/lib/common/validation.js:1413:11)
validateParams (/opt/smartdc/vmapi/lib/endpoints/vms.js:198:16)
/opt/smartdc/vmapi/node_modules/async/lib/async.js:542:21
/opt/smartdc/vmapi/node_modules/async/lib/async.js:222:13
iterate (/opt/smartdc/vmapi/node_modules/async/lib/async.js:123:13)
async.eachSeries (/opt/smartdc/vmapi/node_modules/async/lib/async.js:145:9)
_asyncMap (/opt/smartdc/vmapi/node_modules/async/lib/async.js:221:9)
Object.mapSeries (/opt/smartdc/vmapi/node_modules/async/lib/async.js:211:23)
Object.async.series (/opt/smartdc/vmapi/node_modules/async/lib/async.js:540:19)
Server.listVms (/opt/smartdc/vmapi/lib/endpoints/vms.js:258:11)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
Server.preFilterVms (/opt/smartdc/vmapi/lib/endpoints/vms.js:156:16)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
Server._setApp (/opt/smartdc/vmapi/lib/vmapi.js:358:16)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
Server.parseQueryString (/opt/smartdc/vmapi/node_modules/restify/lib/plugins/query.js:45:17)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
Server.parseDate (/opt/smartdc/vmapi/node_modules/restify/lib/plugins/date.js:42:21)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
Server.parseBody (/opt/smartdc/vmapi/node_modules/restify/lib/plugins/body_parser.js:52:17)
next (/opt/smartdc/vmapi/node_modules/restify/lib/server.js:906:30)
f (/opt/smartdc/vmapi/node_modules/once/once.js:17:25)
IncomingMessage.done (/opt/smartdc/vmapi/node_modules/restify/lib/plugins/body_reader.js:111:17)
IncomingMessage.g (events.js:180:16)
IncomingMessage.EventEmitter.emit (events.js:92:17)
_stream_readable.js:920:16
process._tickDomainCallback (node.js:459:13)
[ Jul 11 18:57:59 Stopping because all processes in service exited. ]


This came with this commit to VMAPI updating from restify 2.7 to 4.x:

commit 3f90d046b790f03236628e02ae02b6111bc0f0eb
Author: Julien Gilli <julien.gilli@joyent.com>
Date:   Fri Jul 8 16:26:51 2016 -0700

    ZAPI-742: Upgrade restify to latest 4.x version

    Reviewed by: Trent Mick <trentm@gmail.com>

The issue is that the restify update resulted in an update of the 'qs'
query string parsign module from version 0.6.6 to 3.1.0. 'qs.parse()'
is used in the restify 'queryParser'. There have been some interesting changes
in qs-land.

The particular breakage is two-fold: First qs 3.0 changed behaviour so that
dot-notation in a query string value will do object parsing:

$ node
> var qs = require('qs')
undefined
> q = qs.parse('tag.smartdc_role=docker')
{ tag: { smartdc_role: 'docker' } }

Where as earlier qs did this:

$ node
> var qs = require('qs');
undefined
> qs.parse('tag.smartdc_role=docker')
{ 'tag.smartdc_role': 'docker' }

This would have been handled more gracefully by VMAPI's validation code
(https://github.com/joyent/sdc-vmapi/blob/3f90d046b790f03236628e02ae02b6111bc0f0eb/lib/common/validation.js#L706-L722):

    return function (params) {
        var errs = [];
        var paramName;
        var tagValue;

        for (paramName in params) {
            if (validatorName(paramName) === 'tag') {
                tagValue = params[paramName];
                if (typeof (tagValue) !== 'string') {
                    errs.push(errors.invalidParamErr(paramName,
                        'Invalid tag: ' + tagValue));
                }
            }
        }

        return errs;
    };

except for the second thing in qs v3: Objects returned by qs.parse are "plain"
objects -- created with 'Object.create(null)' so that there is no inheritance
of the Object prototype methods.

> var qs = require('qs')
undefined
> q = qs.parse('tag.smartdc_role=docker')
{ tag: { smartdc_role: 'docker' } }
> q.toString
undefined
> q.tag.toString
undefined

Because 'toString' and 'valueOf' are not defined, you get the error message
above when attempting to concatenate: 'Invalid tag: ' + tagValue.

qs v4 makes 'plain' objects off by default, 'plainObjects: true' to turn
them back on. See https://github.com/ljharb/qs/pull/98

Restify's queryParser doesn't expose any of these options.


tl;dr: The qs v3 module made some unfortunate defaults changes that have been
made optional in v4 (plainObjects off by default) and v5 (allowDots off by default).
restify 4.x unfortunately picked up qs v3. Note that restify 5.x is using qs "^5.2.0".
There is another wrinkle aside: qs v6 has dropped support for node <v4 (for a bitrot
mission Eran is on, https://github.com/ljharb/qs/issues/124), so restify will need to
stay on qs 5.x until it drops node 0.10 and 0.12 support itself.

Suggestions:

Comments

Comment by Trent Mick
Created at 2016-10-20T02:35:13.000Z
see also:

Comment by Trent Mick
Created at 2016-10-26T20:58:56.000Z
https://github.com/restify/node-restify/pull/1209 is in, restify@4.2.0 is published, RFD 59 notes on restify are up for handling this. See <https://github.com/joyent/rfd/tree/master/rfd/0059#restify> bullet number 3.

Comment by Josh Wilsdon
Created at 2016-10-26T21:42:05.000Z
Updated at 2018-05-07T17:50:22.966Z
I intend to fix this with ZAPI-753.

Comment by Trent Mick
Created at 2016-10-28T02:06:15.000Z
The "suggestions" work is done, but for the VMAPI update to the new restify which joshw is handling in the ticket he mentioned.