New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

list functions in v2.2.0 #1544

Closed
wactbprot opened this Issue Aug 8, 2018 · 42 comments

Comments

Projects
None yet
7 participants
@wactbprot

wactbprot commented Aug 8, 2018

after the upgrade from v2.1.x to v2.2.0 we observe that our list functions
frequently (~half of repeated requests to the same url) return with:

error: "render_error",
reason: "function raised error: (new TypeError("req.query is undefined", "lists.sum", 5)) stacktrace: ([object Object],"noproc")@lists.sum:5 runList(function (head, req) { ...

As can be seen above: the request object req in the list-function(head, req) {..} turns to the string noproc. We toke care of cache issues etc. and found the problem occur with different browsers and even curl.

  • Version used: 2.2.0 (2.2 rc2 worked as I remember, same problem in rc3)
  • Browser Name and version: several browsers and also curl shows the problem
  • Operating System and version (desktop or mobile): desktop, openSuse
@janl

This comment has been minimized.

Member

janl commented Aug 8, 2018

2.2 rc2 worked as I remember

@wactbprot could you verify that’s the case?

@janl janl added the waiting on user label Aug 8, 2018

@wactbprot

This comment has been minimized.

wactbprot commented Aug 8, 2018

We rebuild rc1, rc2 and rc3: I remembered wrong, all the same. The problem is introduced with 2.2.0-rc1.
During the tests we noticed that maybe the request header plays a role: the GETs with good old w3m work. I'll do some research on this...

@janl

This comment has been minimized.

Member

janl commented Aug 8, 2018

@wactbprot thanks!

@wohali wohali added bug and removed waiting on user labels Aug 8, 2018

@wohali

This comment has been minimized.

Member

wohali commented Aug 8, 2018

@wactbprot Are you using eval in your function? This was disabled by default in 2.1.1:

#916

From the release notes:

#916: couchjs now disables eval() and the Function() constructor by default. To restore the original behaviour, add the --eval flag to the definition of the javascript query server in your local.ini file.

@wohali

This comment has been minimized.

Member

wohali commented Aug 8, 2018

FYI I just tested a very basic list function and it worked fine here.

@wohali wohali added waiting on user and removed bug labels Aug 8, 2018

@wactbprot

This comment has been minimized.

wactbprot commented Aug 8, 2018

What we have so far is this:

  • we tried firefox with a simple list function; the following header (shift+page reload) work 100%:
Host: localhost:5984
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:61.0) Gecko/20100101 Firefox/61.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
Connection: keep-alive
Upgrade-Insecure-Requests: 1
Pragma: no-cache
Cache-Control: no-cache

without the last two params (normal page reload) our list returns the error above in ~40%.

  • with chromium neither:
Host: localhost:5984
Connection: keep-alive
Cache-Control: max-age=0
Upgrade-Insecure-Requests: 1
DNT: 1
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.84 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate, br
Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7

nor:

Host: localhost:5984
Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
Upgrade-Insecure-Requests: 1
DNT: 1
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.84 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate, br
Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7

works 100%.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 8, 2018

@wactbprot Are you using eval in your function? This was disabled by default in 2.1.1:

no, no eval() in use

@wohali

This comment has been minimized.

Member

wohali commented Aug 8, 2018

@wactbprot Can you provide a complete example, including the request being issued? Ideally if you can reproduce this with curl and not a browser, I'd appreciate it.

@rnewson

This comment has been minimized.

Member

rnewson commented Aug 8, 2018

we need the actual list function please. I've also tested a simple list function with 2.2.0 and it works as expected.

@janl

This comment has been minimized.

Member

janl commented Aug 8, 2018

and sample docs

@rnewson

This comment has been minimized.

Member

rnewson commented Aug 8, 2018

I've also tested with req.query itself, and that worked too;

curl foo:bar@localhost:15984/db1/_design/foo -XPUT -d '{"_id":"_design/foo","_rev":"3-3b014c7cc4ce97cb961af560fba50e27","views":{"bar":{"map":"function(doc){emit(doc._id);}"}},"lists":{"baz":"function(head,req){start();while(row=getRow()){send(toJSON(req.query));}}"}}'

curl 'foo:bar@localhost:15984/db1/_design/foo/_list/baz/bar?foo=bar'
{"foo":"bar"}{"foo":"bar"}{"foo":"bar"}{"foo":"bar"}%

@wactbprot

This comment has been minimized.

wactbprot commented Aug 8, 2018

  • first: no eval() but require() ...?

Can you provide a complete example, including the request being issued?

hm, I'll try if the error occurs on a empty database

@wactbprot

This comment has been minimized.

wactbprot commented Aug 8, 2018

I can not reproduce the error with new created list functions. The problem remains with the old ones.
I deleted and re-deployed the old function; same behavior. I striped down the old list function to a
start() and send() and get (sometimes):

error: "render_error",
reason: "function raised error: (new TypeError("req.query is undefined", "lists.sum", 19)) stacktrace: ([object Object],"noproc")@lists.sum:19 
runList(function (head, req) {start({headers: {'Content-type': "text/html; charset=utf-8"}});send(req.query.startkey);},[object Object],[object Array])@./share/server/main.js:998 (function (head, req) {start({headers: {'Content-type': "text/html; charset=utf-8"}});send(req.query.startkey);},[object Object],[object Array])@./share/server/main.js:1064 ("_design/az",[object Array],[object Array])@./share/server/main.js:1537 ()@./share/server/main.js:1582 ()@./share/server/main.js:1603 @./share/server/main.js:1 "
}```
@wohali

This comment has been minimized.

Member

wohali commented Aug 8, 2018

@wactbprot Please share:

  • Your OS & version
  • How you installed CouchDB (docker, packages, Windows/Mac binary, from source, etc.)
  • How you installed SpiderMonkey 1.8.5 (Apache packages, vendor packages, from source, etc.)
  • A full list and view function that replicates this problem if you please
@rolfn

This comment has been minimized.

rolfn commented Aug 8, 2018

I am a co-worker of wactbprot and can give some answer:

Your OS & version

openSUSE 42.3 and openSUSE tumbleweed

How you installed CouchDB

I created a rpm file similar to the Fedora rpm file. This worked in the past from 2.0.0 to 2.1.2 without errors.

How you installed SpiderMonkey 1.8.5

I created a rpm file couch-js with the source files from /apache/couchdb-pkg/tree/master/js/rpm

If an Ubuntu 16.4 package for CouchDB 2.2.0 is available we can test the list problem again on this platform.

@wohali

This comment has been minimized.

Member

wohali commented Aug 8, 2018

Hi @rofln,

Yes, Ubuntu 16.04 packages for 2.2.0 are available right now. Please test and let us know if you see the problem there as well. My guess is something about your openSUSE build of couchjs is interfering, but I can't be sure.

You can also test whether or not adding the --eval flag to the definition of the javascript query server in your local.ini file helps, though if you're not using eval() or Function() it shoudln't. This was a change in 2.1.1, #916 , so you should have seen the effect already, but it's worth validating.

@rolfn

This comment has been minimized.

rolfn commented Aug 9, 2018

My guess is something about your openSUSE build of couchjs is interfering, but I can't be sure.

I don't think that this can be the reason. We use the same (!) couchjs code for CouchDB 2.1.2 too without any problems.

More tests will be following.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 9, 2018

The Ubuntu 16.04 packages for 2.2.0 shows the same erroneous behavior as the opensuse packages "compiled" by us. --eval doesn't change anything. Once again: the problem definitive occurs with 2.2.0-rc1. We are not able to provide a simple example for testing etc; we belive, that a certain degree of complexity is part of the problem.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 9, 2018

Any ideas what we can do or test? So far we have to stay at 2.1.

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

@wactbprot Thanks for the confirmation that you see the same issue in 2.2.0 as we build it.

We need a reproducible test case. Please provide us with documents and a list function that reproduce the problem. We'll be more than happy to fix the problem once we have a way to reproduce it.

Looking at the source code, nothing obvious has changed in our couchjs or _list implementations between the releases:

https://github.com/apache/couchdb/tree/master/src/couch/priv/couch_js
https://github.com/apache/couchdb/tree/master/share/server
https://github.com/apache/couchdb/blob/master/src/chttpd/src/chttpd_show.erl

so there's no "smoking gun" here.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 9, 2018

We need a reproducible test case. Please provide us with documents and a list function that reproduce the problem. We'll be more than happy to fix the problem once we have a way to reproduce it.

We really understand that. However:

We are not able to provide a simple example for testing etc;

I spend several hours with the attempt. We were not even able to find a pattern of request fails.

Only one example:
If I use chromium the request fails in half of the requests as reported. If I use curl with the same request header (chrom has the opportunity to generate the curl equivalent) the request works 100%.

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

Hm, that is interesting.

Do you have any sort of reverse web proxy in front of CouchDB? This might be an incompatibility with e.g. nginx, which is commonly misconfigured. We recommend HAProxy for best compatibility - it's what most of the CouchDB clusters at scale use.

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

Follow-up question: Are you using CouchDB's native SSL support (httpsd)?

@wactbprot

This comment has been minimized.

wactbprot commented Aug 9, 2018

No proxy no SSL, in most of the tests I use a simple request to localhost w/o auth.

May I ask the other way around: can you try to find out or imagine under which conditions the second parameter of the anonymous list function catn become noproc? Is noproc a Erlang atom?

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

@wactbprot I'm just the issue triager, someone else will be along in a bit to dig deeper on this.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 9, 2018

great!

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

The trimmed-down list function, in a design document:

{
  "language": "javascript",
  "views": {
    "variants": {
      "map": "function(doc) {emit(doc.foo, doc.bar);}"
    }
  },
  "lists": {
    "results": "function(head, req) { start({ \"headers\": {\"Content-type\": \"text/html; charset=utf-8\"}}); send(req.query.startkey); }"
  }
}

On a single line:

'{"language":"javascript","views":{"variants":{"map":"function(doc) {emit(doc.foo, doc.bar);}"}},"lists":{"results":"function(head, req) { start({ \"headers\": {\"Content-type\": \"text/html; charset=utf-8\"}}); send(req.query.startkey); }"}}'

Any sort of document will do for this.

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

One last idea - if you turn up couchdb logging to debug level, do you see anything useful in the logs when this fails?

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

@wactbprot here is my current test case. The above doc is stored into /abc/_design/lists-1544. I then created a few sample docs in the /abc/ db, though it doesn't matter for this list function.

I have a file headers.txt with the following content:

Host: localhost:5984
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:61.0) Gecko/20100101 Firefox/61.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
Connection: keep-alive
Upgrade-Insecure-Requests: 1

I'm then issuing the following command (note: my couchdb is running on port 15984)

while true; do curl -v -H "$(cat headers.txt)" localhost:15984/abc/_design/lists-1544/_list/results/variants?startkey=\"abc\" 2>&1 | grep render_error; done

So far every request is succeeding. Are you able to confirm whether the above fails for you at all?

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

OK, I ran the test like that for 40 minutes, with no reproduction. @rnewson ran tests too. Neither one of us were able to reproduce with this harness. Sorry :(

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 9, 2018

We were able to reproduce more or less reliably in this way:

  • make a VM, we use Parallels, 2 cores, 1GB, Xenial in this case
  • build 2.2 cluster from sources and run, 1 machine with 3 nodes, default cfg
  • log in using browser outside of VM; we use Photon to log in, however it seems insignificant
  • create a bucket, no security
  • replicate some docs into new bucket (we put 250 docs, about 15 Mb JSON in total)
  • make a ddoc with a simple list (very similar to the above) and a view, emitting all docs under same key with full body, like emit('abc', doc);
  • tap view to build the index
  • put request string with _list into browser address bar
  • run list in browser tab
  • log out
  • put VM on pause for 5+ minutes – key point
  • wake up VM
  • Update: Clicking _all_dbs button in Fauxton in this point (it makes 3 _session requests) seem to guarantee an error in the next step
  • reload page with list several times.

Very likely you will see error message like in the issue, often several times. Eventually things become ok.

Not sure, but seems longer VM pauses somehow increase probability of seeing error.

Hope it helps.

@wohali

This comment has been minimized.

Member

wohali commented Aug 9, 2018

@ermouth are you able to upload a couch.log file of this, preferably running at debug level, that captures the problem?

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 9, 2018

[notice] 2018-08-09T20:20:35.356925Z node1@127.0.0.1 <0.9175.0> 9c7987e49e 192.168.0.221:15984 192.168.0.204 root PUT /_node/node1%40127.0.0.1/_config/log/writer 200 ok 3
[debug] 2018-08-09T20:20:35.455855Z node1@127.0.0.1 <0.9175.0> 0409c2af50 cache miss for root
[debug] 2018-08-09T20:20:35.456600Z node1@127.0.0.1 <0.9175.0> 0409c2af50 no record of user root
[debug] 2018-08-09T20:20:35.456628Z node1@127.0.0.1 <0.9175.0> 0409c2af50 timeout 600
[debug] 2018-08-09T20:20:35.456644Z node1@127.0.0.1 <0.9175.0> 0409c2af50 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.458489Z node1@127.0.0.1 <0.9175.0> 0409c2af50 192.168.0.221:15984 192.168.0.204 root PUT /_node/node2%40127.0.0.1/_config/log/file 200 ok 3
[debug] 2018-08-09T20:20:35.556848Z node1@127.0.0.1 <0.9175.0> 62ab441846 cache miss for root
[debug] 2018-08-09T20:20:35.557291Z node1@127.0.0.1 <0.9175.0> 62ab441846 no record of user root
[debug] 2018-08-09T20:20:35.557322Z node1@127.0.0.1 <0.9175.0> 62ab441846 timeout 600
[debug] 2018-08-09T20:20:35.557339Z node1@127.0.0.1 <0.9175.0> 62ab441846 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.564042Z node1@127.0.0.1 <0.9175.0> 62ab441846 192.168.0.221:15984 192.168.0.204 root PUT /_node/node2%40127.0.0.1/_config/log/level 200 ok 7
[debug] 2018-08-09T20:20:35.658361Z node1@127.0.0.1 <0.9175.0> a13da427b3 cache miss for root
[debug] 2018-08-09T20:20:35.658757Z node1@127.0.0.1 <0.9175.0> a13da427b3 no record of user root
[debug] 2018-08-09T20:20:35.658786Z node1@127.0.0.1 <0.9175.0> a13da427b3 timeout 600
[debug] 2018-08-09T20:20:35.658803Z node1@127.0.0.1 <0.9175.0> a13da427b3 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.667073Z node1@127.0.0.1 <0.9175.0> a13da427b3 192.168.0.221:15984 192.168.0.204 root PUT /_node/node2%40127.0.0.1/_config/log/writer 200 ok 9
[debug] 2018-08-09T20:20:35.762182Z node1@127.0.0.1 <0.9175.0> 2498b74eea cache miss for root
[debug] 2018-08-09T20:20:35.762574Z node1@127.0.0.1 <0.9175.0> 2498b74eea no record of user root
[debug] 2018-08-09T20:20:35.762603Z node1@127.0.0.1 <0.9175.0> 2498b74eea timeout 600
[debug] 2018-08-09T20:20:35.762620Z node1@127.0.0.1 <0.9175.0> 2498b74eea Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.770663Z node1@127.0.0.1 <0.9175.0> 2498b74eea 192.168.0.221:15984 192.168.0.204 root PUT /_node/node3%40127.0.0.1/_config/log/file 200 ok 9
[debug] 2018-08-09T20:20:35.861057Z node1@127.0.0.1 <0.9175.0> 6a3749131f cache miss for root
[debug] 2018-08-09T20:20:35.861563Z node1@127.0.0.1 <0.9175.0> 6a3749131f no record of user root
[debug] 2018-08-09T20:20:35.861595Z node1@127.0.0.1 <0.9175.0> 6a3749131f timeout 600
[debug] 2018-08-09T20:20:35.861611Z node1@127.0.0.1 <0.9175.0> 6a3749131f Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.868442Z node1@127.0.0.1 <0.9175.0> 6a3749131f 192.168.0.221:15984 192.168.0.204 root PUT /_node/node3%40127.0.0.1/_config/log/level 200 ok 7
[debug] 2018-08-09T20:20:35.965554Z node1@127.0.0.1 <0.9175.0> 7a783ab565 cache miss for root
[debug] 2018-08-09T20:20:35.966116Z node1@127.0.0.1 <0.9175.0> 7a783ab565 no record of user root
[debug] 2018-08-09T20:20:35.966147Z node1@127.0.0.1 <0.9175.0> 7a783ab565 timeout 600
[debug] 2018-08-09T20:20:35.966164Z node1@127.0.0.1 <0.9175.0> 7a783ab565 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.968346Z node1@127.0.0.1 <0.9175.0> 7a783ab565 192.168.0.221:15984 192.168.0.204 root PUT /_node/node3%40127.0.0.1/_config/log/writer 200 ok 3
[debug] 2018-08-09T20:20:35.975998Z node1@127.0.0.1 <0.9175.0> 12c3cb6078 cache miss for root
[debug] 2018-08-09T20:20:35.976776Z node1@127.0.0.1 <0.9175.0> 12c3cb6078 no record of user root
[debug] 2018-08-09T20:20:35.976914Z node1@127.0.0.1 <0.9175.0> 12c3cb6078 timeout 600
[debug] 2018-08-09T20:20:35.976972Z node1@127.0.0.1 <0.9175.0> 12c3cb6078 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.977352Z node1@127.0.0.1 <0.9175.0> 12c3cb6078 192.168.0.221:15984 192.168.0.204 root GET /_membership 200 ok 2
[debug] 2018-08-09T20:20:35.982064Z node1@127.0.0.1 <0.9175.0> 580192c3c9 cache miss for root
[debug] 2018-08-09T20:20:35.982683Z node1@127.0.0.1 <0.9175.0> 580192c3c9 no record of user root
[debug] 2018-08-09T20:20:35.982714Z node1@127.0.0.1 <0.9175.0> 580192c3c9 timeout 600
[debug] 2018-08-09T20:20:35.982733Z node1@127.0.0.1 <0.9175.0> 580192c3c9 Successful cookie auth as: "root"
[notice] 2018-08-09T20:20:35.983986Z node1@127.0.0.1 <0.9175.0> 580192c3c9 192.168.0.221:15984 192.168.0.204 root GET /_node/node1%40127.0.0.1/_config 200 ok 2
[debug] 2018-08-09T20:20:54.398303Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee cache miss for root
[debug] 2018-08-09T20:20:54.399690Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee no record of user root
[debug] 2018-08-09T20:20:54.399721Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee timeout 600
[debug] 2018-08-09T20:20:54.399743Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee Successful cookie auth as: "root"
[debug] 2018-08-09T20:20:54.409505Z node1@127.0.0.1 <0.10406.0> -------- OS Process Start :: #Port<0.29670>
[debug] 2018-08-09T20:20:54.409797Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Input  :: ["ddoc","new","_design/lists2",{"_id":"_design/lists2","_rev":"1-fe570f308484db16fb22e1fe6a2d803b","language":"javascript","views":{"variants3":{"map":"function(doc) {emit(doc.type , doc);}"}},"lists":{"results":"function(head, req) { start({ \"headers\": {\"Content-type\": \"text/html; charset=utf-8\"}}); var i=0; send (JSON.stringify(req.query)); while (getRow()) {i+=1}; send(i+'\\n\\n');  send (JSON.stringify(req.query)); }","r":"function (head,req) { start({ \"headers\": {\"Content-type\": \"text/html; charset=utf-8\"}}); getRow(); send (JSON.stringify(req)); }"}}]
[debug] 2018-08-09T20:20:54.435704Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Output :: true
[debug] 2018-08-09T20:20:54.435914Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Input  :: ["reset",{"reduce_limit":true,"timeout":5000}]
[debug] 2018-08-09T20:20:54.437088Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Output :: true
[debug] 2018-08-09T20:20:54.441677Z node2@127.0.0.1 <0.10547.0> -------- Opening index for db: shards/40000000-5fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.442628Z node3@127.0.0.1 <0.11553.0> -------- Opening index for db: shards/40000000-5fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.443686Z node1@127.0.0.1 <0.10418.0> -------- Opening index for db: shards/00000000-1fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.445450Z node1@127.0.0.1 <0.10420.0> -------- Opening index for db: shards/40000000-5fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.445183Z node3@127.0.0.1 <0.11554.0> -------- Opening index for db: shards/00000000-1fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.447518Z node1@127.0.0.1 <0.10452.0> -------- Opening index for db: shards/a0000000-bfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.447554Z node1@127.0.0.1 <0.10453.0> -------- Opening index for db: shards/60000000-7fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.443470Z node2@127.0.0.1 <0.10549.0> -------- Opening index for db: shards/00000000-1fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.455017Z node3@127.0.0.1 <0.11585.0> -------- Opening index for db: shards/a0000000-bfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.455684Z node3@127.0.0.1 <0.11589.0> -------- Opening index for db: shards/20000000-3fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.456879Z node3@127.0.0.1 <0.11581.0> -------- Opening index for db: shards/c0000000-dfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.456994Z node2@127.0.0.1 <0.10579.0> -------- Opening index for db: shards/60000000-7fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.456913Z node3@127.0.0.1 <0.11583.0> -------- Opening index for db: shards/60000000-7fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.457033Z node2@127.0.0.1 <0.10577.0> -------- Opening index for db: shards/e0000000-ffffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.457602Z node2@127.0.0.1 <0.10576.0> -------- Opening index for db: shards/c0000000-dfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.457688Z node3@127.0.0.1 <0.11598.0> -------- Opening index for db: shards/e0000000-ffffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.457843Z node2@127.0.0.1 <0.10587.0> -------- Opening index for db: shards/a0000000-bfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.458505Z node2@127.0.0.1 <0.10585.0> -------- Opening index for db: shards/80000000-9fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.458850Z node2@127.0.0.1 <0.10586.0> -------- Opening index for db: shards/20000000-3fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.461261Z node3@127.0.0.1 <0.11599.0> -------- Opening index for db: shards/80000000-9fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.463292Z node1@127.0.0.1 <0.10451.0> -------- Opening index for db: shards/80000000-9fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.463377Z node1@127.0.0.1 <0.10458.0> -------- Opening index for db: shards/e0000000-ffffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.463455Z node1@127.0.0.1 <0.10446.0> -------- Opening index for db: shards/20000000-3fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.464030Z node1@127.0.0.1 <0.10465.0> -------- Opening index for db: shards/c0000000-dfffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9"
[debug] 2018-08-09T20:20:54.474253Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Input  :: ["ddoc","_design/lists2",["lists","results"],[{"total_rows":260,"offset":0},"noproc"]]
[debug] 2018-08-09T20:20:54.476042Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Output :: ["log","function raised error: (new TypeError(\"chunk is undefined\", \"/home/parallels/couchdb/share/server/main.js\", 860)) \u000astacktrace: send((void 0))@/home/parallels/couchdb/share/server/main.js:860\u000a([object Object],\"noproc\")@lists.results:1\u000arunList(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:998\u000a(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:1064\u000a(\"_design/lists2\",[object Array],[object Array])@/home/parallels/couchdb/share/server/main.js:1537\u000a()@/home/parallels/couchdb/share/server/main.js:1582\u000a()@/home/parallels/couchdb/share/server/main.js:1603\u000a@/home/parallels/couchdb/share/server/main.js:1\u000a"]
[info] 2018-08-09T20:20:54.476171Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Log :: function raised error: (new TypeError("chunk is undefined", "/home/parallels/couchdb/share/server/main.js", 860)) 
stacktrace: send((void 0))@/home/parallels/couchdb/share/server/main.js:860
([object Object],"noproc")@lists.results:1
runList(function (head, req) {start({headers: {'Content-type': "text/html; charset=utf-8"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + "\n\n");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:998
(function (head, req) {start({headers: {'Content-type': "text/html; charset=utf-8"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + "\n\n");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:1064
("_design/lists2",[object Array],[object Array])@/home/parallels/couchdb/share/server/main.js:1537
()@/home/parallels/couchdb/share/server/main.js:1582
()@/home/parallels/couchdb/share/server/main.js:1603
@/home/parallels/couchdb/share/server/main.js:1

[debug] 2018-08-09T20:20:54.476272Z node1@127.0.0.1 <0.10406.0> -------- OS Process #Port<0.29670> Output :: ["error","render_error","function raised error: (new TypeError(\"chunk is undefined\", \"/home/parallels/couchdb/share/server/main.js\", 860)) \u000astacktrace: send((void 0))@/home/parallels/couchdb/share/server/main.js:860\u000a([object Object],\"noproc\")@lists.results:1\u000arunList(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:998\u000a(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:1064\u000a(\"_design/lists2\",[object Array],[object Array])@/home/parallels/couchdb/share/server/main.js:1537\u000a()@/home/parallels/couchdb/share/server/main.js:1582\u000a()@/home/parallels/couchdb/share/server/main.js:1603\u000a@/home/parallels/couchdb/share/server/main.js:1\u000a"]
[error] 2018-08-09T20:20:54.477098Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee OS Process Error <0.10406.0> :: {<<"render_error">>,<<"function raised error: (new TypeError(\"chunk is undefined\", \"/home/parallels/couchdb/share/server/main.js\", 860)) \nstacktrace: send((void 0))@/home/parallels/couchdb/share/server/main.js:860\n([object Object],\"noproc\")@lists.results:1\nrunList(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:998\n(function (head, req) {start({headers: {'Content-type': \"text/html; charset=utf-8\"}});var i = 0;send(JSON.stringify(req.query));while (getRow()) {i += 1;}send(i + \"\\n\\n\");send(JSON.stringify(req.query));},[object Object],[object Array])@/home/parallels/couchdb/share/server/main.js:1064\n(\"_design/lists2\",[object Array],[object Array])@/home/parallels/couchdb/share/server/main.js:1537\n()@/home/parallels/couchdb/share/server/main.js:1582\n()@/home/parallels/couchdb/share/server/main.js:1603\n@/home/parallels/couchdb/share/server/main.js:1\n">>}
[notice] 2018-08-09T20:20:54.477467Z node1@127.0.0.1 <0.9175.0> 3abfaec7ee 192.168.0.221:15984 192.168.0.204 root GET /zx/_design/lists2/_list/results/variants3?startkey=%22d100%22&limit=2 500 ok 79
[debug] 2018-08-09T20:20:55.801987Z node2@127.0.0.1 <0.10549.0> -------- Index shutdown by monitor notice for db: shards/00000000-1fffffff/zx.1533837982 idx: _design/lists2
[debug] 2018-08-09T20:20:55.802428Z node2@127.0.0.1 <0.10549.0> -------- Closing index for db: shards/00000000-1fffffff/zx.1533837982 idx: _design/lists2 sig: "fcc86cc6cd04545f85bfd0803f6abfc9" because normal

Ddoc is bit different, but very slightly.

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 9, 2018

Another one log2.log

Here I reload Photon, and then immediately have errors several times, and then finally have expected response.

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 10, 2018

OS Process #Port<0.29670> Input :: ["ddoc","_design/lists2",["lists","results"],[{"total_rows":260,"offset":0},"noproc"]]

Here I see noproc msg instead of req obj. Seems it’s the only place able to return "noproc" string instead of req obj is https://github.com/apache/couchdb/blob/2.2.x/src/couch_mrview/src/couch_mrview_show.erl#L367-L377. However, I can’t see how it happens because I don’t clearly understand what this code does.

@wactbprot

This comment has been minimized.

wactbprot commented Aug 10, 2018

We found the region where the problem is introduced:

f6a771147ba488f80a7d29491263d19088d0eefb (t13) Implement pluggable storage engines
8e34ce382dcdf16a2d68a0f0ac45f300c91e6844 (t12) Add legacy storage engine implementation
fb2b046b288405f60a261552cacd57584fce72fd (t16) Add couch_db_engine module
364ea209250df169f0c7425cf0003e20a5a2d28d (t15) Remove old rolling reboot upgrade code
083239353e919e897b97e8a96ee07cb42ca4eccd (t14) Prevent chttpd multipart zombie processes
6d959a7acab7d0ff110c7799f3295b6193f45c2f (t17) Avoid unconditional retries in replicator's http client
302bd8b8b193186b920c56c918bb2bb7edc4be8a (t11) feat: update mochiweb to 2.17.0
49
  • branch t11 works
  • branch t13 don't
  • the branches in between don't compile

rnewson added a commit that referenced this issue Aug 10, 2018

@rnewson

This comment has been minimized.

Member

rnewson commented Aug 10, 2018

@wactbprot @ermouth Can you try the above patch (#1553)?

I think what's happening is that an error from somewhere else is getting swapped for the req.query value. The patch above should ensure we wait for the right 'DOWN' message.

I expect a) you no longer get the error reported b) your log shows a new error that I would very much like to see.

@mtabb13

This comment has been minimized.

mtabb13 commented Aug 10, 2018

I have come across a bug in v2.1.2 querying _changes. It doesn't fail every time, maybe once or twice a day. The application code calling this endpoint runs on a 30 second polling interval. The same code worked in 2.0 and 2.1.1 without problems. I get the following error:

fabric_rpc:changes/3 error:{badmatch,{'EXIT',noproc}} [{couch_file,pread_binary,2,[{file,"src/couch_file.erl"},{line,169}]},{couch_file,pread_term,2,[{file,"src/couch_file.erl"},{line,157}]},{couch_btree,get_node,2,[{file,"src/couch_btree.erl"},{line,434}]},{couch_btree,reduce_stream_node,11,[{file,"src/couch_btree.erl"},{line,619}]},{couch_btree,fold_reduce,4,[{file,"src/couch_btree.erl"},{line,81}]},{couch_db,count_changes_since,2,[{file,"src/couch_db.erl"},{line,1407}]},{fabric_rpc,changes,4,[{file,"src/fabric_rpc.erl"},{line,80}]},{rexi_server,init_p,3,[{file,"src/rexi_server.erl"},{line,139}]}]

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 11, 2018

@rnewson We‘ll test the patch on Tuesday. Could you please explain shortly what that code intended to do? Particularly, why so tricky way to call a fn is used?

@wactbprot

This comment has been minimized.

wactbprot commented Aug 12, 2018

I expect a) you no longer get the error reported b) your log shows a new error that I would very much like to see.

@rnewson patch fixes our list issues completely.
on b) don't observe any error messages related to our list requests (log level debug)

@couchdbteam Thanks a lot for your work!

@wohali

This comment has been minimized.

Member

wohali commented Aug 12, 2018

@wactbprot Thanks for the confirmation. We'll get this update into the very next release of CouchDB.

@wohali wohali removed the waiting on user label Aug 12, 2018

@wohali wohali closed this Aug 12, 2018

@ermouth

This comment has been minimized.

Contributor

ermouth commented Aug 14, 2018

I also confirm that the issue seems to be fixed with the patch.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment