search

iDigBio / idigbio-search-api

Server-side code driving iDigBio's search functionality.
GNU General Public License v3.0
24 stars 5 forks source link

literal string "OK" and HTTP status code 200 returned instead of error or JSON #29

Open danstoner opened 6 years ago

danstoner commented 6 years ago

Some requests to search api generate a return of the literal string "OK" rather than a proper JSON response.

It is possible this happens in situation where route does not exist.

$ http 'https://search.idigbio.org/v2/does_not_exist/'
HTTP/1.1 200 OK
Cache-Control: public, max-age=300
Content-Length: 2
Content-Type: text/plain; charset=utf-8
Date: Fri, 16 Mar 2018 19:53:27 GMT
Last-Modified: Fri, 09 Mar 2018 14:29:26 GMT
Vary: Accept-Encoding, Origin

OK
danstoner commented 6 years ago

This behavior is caused by code in: src/middleware/jsonErrors.js

The 200 OK is being generated elsewhere. Completely removing jsonErrors.js reference from app.js does not change the behavior.

danstoner commented 6 years ago

Possibly relevant:

https://github.com/alexmingoia/koa-router/issues/257

We are currently using koa, koa-router.

That issue already mentioned in commit history.

b17b83bcaeecdf62ab348f0ee6f6ace904dc4ab7

danstoner commented 6 years ago

The test suite already has cases that would catch these instances where 404 should be received instead of 200.

Seems that the travis docker build / test run provides different results than a local run. Example, all passing:

https://travis-ci.org/iDigBio/idigbio-search-api/builds/355542055

but on my laptop I get "text" content type instead of JSON.

dstoner@dstoner-ultra:~/git/idigbio-search-api$ npm test
...
  ● Management routes › should 404 on /manage

    expected "Content-Type" matching /json/, got "text/plain; charset=utf-8"

  ● View › basic › should 404 on missing publishers

    expected "Content-Type" matching /json/, got "text/plain; charset=utf-8"

  ● View › basic › should 404 on missing records

    expected "Content-Type" matching /json/, got "text/plain; charset=utf-8"

  ● View › basic › should 404 on missing mediarecords

    expected "Content-Type" matching /json/, got "text/plain; charset=utf-8"

  ● Search › basicGET › should error on invalid search terms

    expected "Content-Type" matching /json/, got "text/plain; charset=utf-8"
...
danstoner commented 6 years ago

Travis-CI build services use docker images from:

https://docs.travis-ci.com/user/common-build-problems/#Running-a-Container-Based-Docker-Image-Locally

Ours is "different".

Some info from the currently running docker container (our prod) which is one of the places where the "OK" problem exists.

Outside the container:

# docker images
REPOSITORY                   TAG                 IMAGE ID            CREATED             SIZE
idigbio/idigbio-search-api   v1.0.5              9ba190f2c1e3        4 months ago        613 MB

# docker container ls
CONTAINER ID        IMAGE                               COMMAND                  CREATED             STATUS              PORTS                      NAMES
e69451695885        idigbio/idigbio-search-api:v1.0.5   "npm start"              4 months ago        Up 2 weeks          0.0.0.0:19196->19196/tcp   idigbio-search-api

Start a shell in the container...

# docker exec -it e69451695885 bash -l
www-data@e69451695885:~$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 16.04.3 LTS
Release:    16.04
Codename:   xenial
www-data@e69451695885:~$ uname -a
Linux e69451695885 4.4.0-96-generic #119-Ubuntu SMP Tue Sep 12 14:59:54 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Node environment inside the container:

~$ node --version
v6.11.5
~$ nodejs --version
v6.11.5
~$ npm --version
3.10.10
~$ yarn --version
1.2.1

www-data@e69451695885:~$ npm list --depth=0
idb-search-api@1.0.5 /var/www
+-- babel-cli@6.26.0
+-- babel-jest@18.0.0
+-- babel-plugin-module-resolver@2.7.1
+-- babel-plugin-transform-promise-to-bluebird@1.1.1
+-- babel-polyfill@6.26.0
+-- babel-preset-node6@11.0.0
+-- babel-preset-stage-3@6.24.1
+-- babel-register@6.26.0
+-- bluebird@3.5.1
+-- body-parser@1.18.2
+-- cache-manager-redis@0.4.0
+-- chai@3.5.0
+-- chroma-js@1.3.4
+-- compression@1.7.1
+-- cors@2.8.4
+-- elasticsearch@12.1.3
+-- eslint@3.19.0
+-- eslint-import-resolver-babel-module@3.0.0
+-- eslint-plugin-import@2.8.0
+-- hashids@1.1.2
+-- hiredis@0.5.0
+-- jest@18.1.0
+-- kcors@2.2.1
+-- koa@2.3.0
+-- koa-adapter@0.0.3
+-- koa-bodyparser@3.2.0
+-- koa-compress@2.0.0
+-- koa-ctx-cache-control@1.0.1
+-- koa-proxy@0.8.0
+-- koa-router@7.2.1
+-- lodash@4.17.4
+-- mapnik@3.6.2
+-- morgan@1.9.0
+-- ngeohash@0.6.0
+-- node-pre-gyp@0.6.38 extraneous
+-- nodemon@1.12.1
+-- redis@2.8.0
+-- redis-mock@0.16.0
+-- request@2.83.0
+-- request-promise@4.2.2
+-- sol-redis-pool@0.3.3
+-- supertest@3.0.0
`-- winston@2.4.0

npm ERR! extraneous: node-pre-gyp@0.6.38 /var/www/node_modules/node-pre-gyp

www-data@e69451695885:~$ ls -latr
total 1608976
-rw-rw-r--   1 root     root         134733 Oct 30 21:14 yarn.lock
drwxrwxr-x   6 root     root           4096 Oct 30 21:14 src
-rw-rw-r--   1 root     root           2313 Oct 30 21:14 package.json
-rw-rw-r--   1 root     root           1720 Oct 30 21:14 index.js
drwxrwxr-x   4 root     root           4096 Oct 30 21:14 __tests__
-rw-rw-r--   1 root     root           1280 Oct 30 21:14 README.md
-rw-rw-r--   1 root     root          35121 Oct 30 21:14 LICENSE
-rw-rw-r--   1 root     root           6068 Oct 30 21:14 .jshintrc
-rw-rw-r--   1 root     root             88 Oct 30 21:14 .gitignore
-rw-rw-r--   1 root     root           7091 Oct 30 21:14 .eslintrc.js
-rw-rw-r--   1 root     root            114 Oct 30 21:14 .dockerignore
-rw-rw-r--   1 root     root            465 Oct 30 21:14 .checkbuild
-rw-rw-r--   1 root     root            224 Oct 30 21:14 .babelrc
drwxr-xr-x   3 www-data www-data       4096 Oct 30 21:15 .yarn
drwxr-xr-x   3 www-data www-data       4096 Oct 30 21:15 .node-gyp
drwxr-xr-x 618 www-data www-data      20480 Oct 30 21:15 node_modules
drwxr-xr-x   4 www-data www-data       4096 Oct 30 21:15 .cache
drwxr-xr-x   6 www-data www-data       4096 Oct 30 21:15 build
drwxr-xr-x  28 root     root           4096 Jan 23 13:21 ..
drwxr-xr-x  10 www-data www-data       4096 Feb 28 20:19 .
-rw-------   1 www-data www-data 1724649472 Feb 28 20:27 core

Unfortunately, cannot currently run tests since they all depend on mock directories existing in places where the www-data user cannot create them.

www-data@e69451695885:~$ ./node_modules/.bin/jest manage
jest-haste-map: duplicate manual mock found:
  Module name: searchShim
  Duplicate Mock path: /var/www/src/__mocks__/searchShim.js
This warning is caused by two manual mock files with the same file name.
Jest will use the mock file found in: 
/var/www/src/__mocks__/searchShim.js
 Please delete one of the following two files: 
 /var/www/build/__mocks__/searchShim.js
/var/www/src/__mocks__/searchShim.js

jest-haste-map: duplicate manual mock found:
  Module name: redisclient
  Duplicate Mock path: /var/www/src/__mocks__/redisclient.js
This warning is caused by two manual mock files with the same file name.
Jest will use the mock file found in: 
/var/www/src/__mocks__/redisclient.js
 Please delete one of the following two files: 
 /var/www/build/__mocks__/redisclient.js
/var/www/src/__mocks__/redisclient.js

jest-haste-map: duplicate manual mock found:
  Module name: esclient
  Duplicate Mock path: /var/www/src/__mocks__/esclient.js
This warning is caused by two manual mock files with the same file name.
Jest will use the mock file found in: 
/var/www/src/__mocks__/esclient.js
 Please delete one of the following two files: 
 /var/www/build/__mocks__/esclient.js
/var/www/src/__mocks__/esclient.js

 FAIL  __tests__/controllers/test-manage.js
  ● Test suite failed to run

    ENOENT: no such file or directory, lstat '/var/www/__tests__/mock'
        at Error (native)

      at Object.fs.lstatSync (fs.js:995:11)
      at Object.lstatSync (node_modules/graceful-fs/polyfills.js:297:22)
      at Object.realpathSync (fs.js:1676:21)
      at Object.<anonymous> (src/__mocks__/esclient.js:32:1601)
      at Object.<anonymous> (src/searchShim.js:5:43)

Test Suites: 1 failed, 1 total
Tests:       0 total
Snapshots:   0 total
Time:        3.155s
Ran all test suites matching "manage".

Inside the container I have no editors, no sudo, or (easy) ability to install an editor.

Will try to figure out how to mount / create those directory points for mock.

danstoner commented 6 years ago

Possible big find is that the "node" command inside the travis container maps to node v8.9.1 but "nodejs" maps to v6.13.1.

The "test"command is package.json is specified as "NODE_ENV=test BLUEBIRD_DEBUG=1 jest" which does not make it clear which node command is used (v6 or v8).

Here is info from inside the travis-ci container:

No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 14.04.5 LTS
Release:    14.04
Codename:   trusty
travis@a142a143257f:~/idigbio-search-api$ uname -a
Linux a142a143257f 3.13.0-137-generic #186-Ubuntu SMP Mon Dec 4 19:09:19 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
travis@a142a143257f:~/idigbio-search-api$ node --version
v8.9.1
travis@a142a143257f:~/idigbio-search-api$ nodejs --version
v6.13.1
travis@a142a143257f:~/idigbio-search-api$ npm --version
5.5.1
travis@a142a143257f:~/idigbio-search-api$ yarn --version
1.3.2

travis@a142a143257f:~/idigbio-search-api$ npm list --depth=0
idb-search-api@1.0.5 /home/travis/idigbio-search-api
├── babel-cli@6.26.0
├── babel-jest@18.0.0
├── babel-plugin-module-resolver@2.7.1
├── babel-plugin-transform-promise-to-bluebird@1.1.1
├── babel-polyfill@6.26.0
├── babel-preset-node6@11.0.0
├── babel-preset-stage-3@6.24.1
├── babel-register@6.26.0
├── bluebird@3.5.1
├── body-parser@1.18.2
├── cache-manager-redis@0.4.0
├── chai@3.5.0
├── chroma-js@1.3.6
├── compression@1.7.2
├── cors@2.8.4
├── elasticsearch@12.1.3
├── eslint@3.19.0
├── eslint-import-resolver-babel-module@3.0.0
├── eslint-plugin-import@2.9.0
├── hashids@1.1.4
├── hiredis@0.5.0
├── jest@18.1.0
├── kcors@2.2.1
├── koa@2.5.0
├── koa-adapter@0.0.3
├── koa-bodyparser@3.2.0
├── koa-compress@2.0.0
├── koa-ctx-cache-control@1.0.1
├── koa-proxy@0.8.0
├── koa-router@7.4.0
├── lodash@4.17.5
├── mapnik@3.7.1
├── morgan@1.9.0
├── ngeohash@0.6.0
├── node-pre-gyp@0.6.39
├── nodemon@1.17.2
├── redis@2.8.0
├── redis-mock@0.16.0
├── request@2.85.0
├── request-promise@4.2.2
├── sol-redis-pool@0.3.3
├── supertest@3.0.0
└── winston@2.4.1
danstoner commented 6 years ago

See some quirks:

https://github.com/yarnpkg/yarn/issues/1142

Inside Dockerfile, we are currently installing nodejs from apt. Inside Dockerfile, we are currently install yarn via npm.

On the travis-ci image, "node" is pre-installed (and I believe is version 8).

travis@a142a143257f:~/idigbio-search-api$ which npm
/home/travis/.nvm/versions/node/v8.9.1/bin/npm
travis@a142a143257f:~/idigbio-search-api$ which yarn
/usr/local/bin/yarn
travis@a142a143257f:~/idigbio-search-api$ which node
/home/travis/.nvm/versions/node/v8.9.1/bin/node
travis@a142a143257f:~/idigbio-search-api$ which nodejs
/usr/bin/nodejs
danstoner commented 6 years ago

The travis docker image is based on Trusty (14.04), the idigbio-search-api docker image is based on Xenial (16.04).

danstoner commented 6 years ago

I got the code working on my desktop and began testing again, seems to have something to do with the presence of the NODE_ENV=test environment variable, or if the caching layer / updateLastModified is present.

Using url of localhost:19196/v2/search/does-not-exist

Yarn start in "prod" mode, get HTTP 200:

dstoner@dstoner-thinkster:~/git/idigbio-search-api$ yarn start
yarn run v1.5.1
$ node index.js
2018-03-22T20:24:47.673Z - info: Found updates to lastModified: {"records":"2018-03-21T11:17:20.187Z","mediarecords":"2018-03-21T11:04:57.305Z","recordsets":"2018-03-21T15:57:28.740Z","publishers":"2018-03-09T16:34:08.811Z"}
2018-03-22T20:24:47.675Z - info: updateLastModified durationMs=3598
2018-03-22T20:24:47.791Z - info: App warmup finished
2018-03-22T20:24:47.794Z - info: Server(main) listening on port 19196
2018-03-22T20:25:16.897Z - info: ::ffff:127.0.0.1 - "GET /v2/search/does-not-exist HTTP/1.1" 200 2 - 8.005 ms
2018-03-22T20:29:52.229Z - info: updateLastModified durationMs=4437
^C2018-03-22T20:31:25.062Z - info: Server(main) received signal SIGINT, attempt exit
2018-03-22T20:31:25.062Z - info: Server(main) finished closing, exiting

Start with NODE_ENV=test, get HTTP 404:

dstoner@dstoner-thinkster:~/git/idigbio-search-api$ NODE_ENV=test node index.js
2018-03-22T20:31:29.435Z - debug: Querying recordsets list
1737
2018-03-22T20:31:33.636Z - info: recordsets:5e543256c480ac577d30f76f9120eb74 durationMs=4201
2018-03-22T20:31:33.640Z - info: Server(main) listening on port 19196
2018-03-22T20:31:42.013Z - info: ::ffff:127.0.0.1 - "GET /v2/search/does-not-exist HTTP/1.1" 404 38 - 5.233 ms

I also noticed that the behavior was "correct" (e.g. giving the 404) when running in prod mode but while a network outage / service disruption was occurring and elasticsearch was not available.

dstoner@dstoner-thinkster:~/git/idigbio-search-api$ yarn start
yarn run v1.5.1
$ node index.js
2018-03-22T20:11:15.235Z - error: Failed updating last modified Error: Request Timeout after 30000ms
    at /home/dstoner/git/idigbio-search-api/node_modules/elasticsearch/src/lib/transport.js:336:15
    at Timeout.<anonymous> (/home/dstoner/git/idigbio-search-api/node_modules/elasticsearch/src/lib/transport.js:365:7)
    at ontimeout (timers.js:386:11)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5)
2018-03-22T20:11:15.237Z - info: updateLastModified durationMs=30024
2018-03-22T20:11:15.239Z - info: App warmup finished
2018-03-22T20:11:15.243Z - info: Server(main) listening on port 19196
2018-03-22T20:11:39.887Z - info: ::ffff:127.0.0.1 - "GET /v2/search/does-not-exist HTTP/1.1" 404 38 - 7.362 ms
danstoner commented 6 years ago

"prod" version requires actual redis. So to test "prod" I have to get redis running locally.