Sporadic `unknown_error : normal` errors

[flimzy]

Occasionally, when using Cookie auth, the /_all_docs endpoint returns 401, and logs an unusual error. I have observed this on both the /_users and /_replicator databases. Unknown if it happens on non-system databases.

Expected Behavior

I would expect a normal response

Current Behavior

Two log samples (both from CouchDB 2.2.0 running in Docker):

[notice] 2018-09-10T19:41:21.627729Z nonode@nohost <0.718.0> 631255b1ec localhost:6004 172.17.0.1 undefined GET /_users/_all_docs?include_docs=true 401 ok 1
[error] 2018-09-10T19:41:21.639919Z nonode@nohost <0.719.0> ec87d65d26 req_err(2525593956) unknown_error : normal
[<<"chttpd:catch_error/3 L353">>,<<"chttpd:handle_req_after_auth/2 L319">>,<<"chttpd:process_request/1 L300">>,<<"chttpd:handle_request_int/1 L240">>,<<"mochiweb_http:headers/6 L124">>,<<"proc_lib:init_p_do_apply/3 L247">>]

[notice] 2018-09-10T19:46:18.065472Z nonode@nohost <0.719.0> 1e9079ba74 localhost:6004 172.17.0.1 undefined GET /_replicator/_all_docs?include_docs=true 401 ok 3
[error] 2018-09-10T19:46:18.069496Z nonode@nohost <0.720.0> f23a984706 req_err(2525593956) unknown_error : normal
[<<"chttpd:catch_error/3 L353">>,<<"chttpd:handle_req_after_auth/2 L319">>,<<"chttpd:process_request/1 L300">>,<<"chttpd:handle_request_int/1 L240">>,<<"mochiweb_http:headers/6 L124">>,<<"proc_lib:init_p_do_apply/3 L247">>]

Steps to Reproduce (for bugs)

As stated above, this is a sporadic error. It doesn't always happen, but the requests that generated the above errors:

GET /_users/_all_docs?include_docs=true HTTP/1.1
Host: localhost:6004
Accept: application/json
Content-Type: application/json
Cookie: AuthSession=YWRtaW46NUI5NkM4RTE6pxr5rMbRBHJgbCdnRzQO0JBuzcI
User-Agent: Kivik CouchDB driver/2.0.0-prerelease (Language=go1.8.7; Platform=amd64/linux)

GET /_replicator/_all_docs?include_docs=true HTTP/1.1
Host: localhost:6004
Accept: application/json
Content-Type: application/json
Cookie: AuthSession=YWRtaW46NUI5NkNBMEE6UJcyxbwz2W6vinTcScdUNX5iQcw
User-Agent: Kivik CouchDB driver/2.0.0-prerelease (Language=go1.9.7; Platform=amd64/linux)

Context

Your Environment

I have observed this on CouchDB 1.7.1, 2.0.0, 2.1.2, and 2.2.0, but only in Travis-CI on my Kivik project. I have been unable thus far to reproduce this locally on any version.

I will continue to try to find a reliable reproduction case.

[nickva]

Interesting find, @flimzy

I have seen this error before as well. But don't have a good explanation for it yet. I wonder how it correlates with Erlang versions. For example, have you seen it on some Erlang versions (20.0) happen more than on others

[flimzy]

I've been testing against the official Docker images for CouchDB 1.7.1 through 2.2.0, which corresponds with Erlang OTP/17 through Erlang OTP/19, respectively. I have seen the error on every version, and have not noticed a higher occurrence on any specific version, but I also likely would not have noticed if one version happened more than the other, since a single failure will cause my test suite to report a failure.

[wohali]

I'd like to fix this in 2.3.0, but without more info from @nickva on a possible reason, I'm going to move it out of this milestone.

[jaydoane]

I tried to repro using this very simple test:

  test "https://github.com/apache/couchdb/issues/1600", _ctx do
    sess = Couch.login("adm", "pass")
    target_db = "_users" # also tried _replicator here
    for _i <- 0..10000 do
      resp = Couch.Session.get(sess, "/#{target_db}/_all_docs?include_docs=true")
      assert resp.status_code == 200
    end
  end

but it ran to completion on several attempts.

@nickva do you recall whether you saw that error from a containerized or bare metal couch?

@flimzy how many documents were in your _users and _replicator dbs when you saw that issue? Since you were using the official docker images, were those just single node "clusters"?

[wohali]

@flimzy without a solid reproducible test case, I'm afraid I have to remove this from the 2.3.0 milestone.

We'd love to get back to this once there's a reliable, reproducible test case.

[natevw]

Fwiw, I'm seeing something quite similar on a view request under 2.3.0 (macOS application, running with project-specific vm.args and local.ini configuration). The database is ?q=1&n=1, and note that it is a user database rather than a system one.

3:19:30 PM dev_db.1  |  [notice] 2019-01-25T23:19:30.658485Z dev_env-couchdb@localhost <0.29058.20> 066f90a8b8 localhost:4100 127.0.0.1 admin GET /my-db
3:19:30 PM dev_db.1  |  >  /_design/my-app/_view/data_by_user_unit_and_seq?startkey=%5B%22alice%22%2C%22unit-9494675355963408%22%2C1342%5D&endkey=%5B%22ali
3:19:30 PM dev_db.1  |  >  ce%22%2C%22unit-9494675355963408%22%2C%7B%7D%5D&include_docs=true&limit=4294967295 200 ok 3
3:19:30 PM dev_web.1 |  POLL GOT null { total_rows: 296, offset: 292, rows: [] } for 1342
3:19:31 PM dev_db.1  |  [error] 2019-01-25T23:19:31.030654Z dev_env-couchdb@localhost <0.25965.20> e181293c16 req_err(1125717067) unknown_error : normal
3:19:31 PM dev_db.1  |      [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_req
3:19:31 PM dev_db.1  |  >  uest_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]

It does not happen every time the view is polled. In fact it seems to happen only once, [have now seen double error messages] a little while after whenever my middleware process gets force-restarted. (The CouchDB instance is not getting restarted very frequently.) The middleware process includes a continuous changes watcher via fermata-couchdb's watchChanges helper as well as a number of database/view calls.

[natevw]

I think at least in my case these errors are simply a result of the client dropping its connection to CouchDB. I added some code to my middleware in support of a little experiment:

• Each time my middleware starts, it randomly decides whether to fetch continuous changes.
• I made sure to avoid any other requests to my middleware and therefore to CouchDB

Here's a sample log:

4:04:33 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:04:34 PM dev_web.1 |  not monitoring changes
4:04:34 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db

4:04:54 PM dev_web.1 |  Program node middleware.js exited with code null
4:04:54 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:04:54 PM dev_web.1 |  not monitoring changes
4:04:54 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db

4:05:14 PM dev_web.1 |  Program node middleware.js exited with code null
4:05:14 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:05:15 PM dev_web.1 |  MONITORING CHANGES
4:05:15 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db

4:05:38 PM dev_web.1 |  Program node middleware.js exited with code null
4:05:38 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:05:38 PM dev_web.1 |  MONITORING CHANGES
4:05:38 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db
4:05:44 PM dev_db.1  |  [error] 2019-01-26T00:05:44.996419Z dev_env-couchdb@localhost <0.13577.22> 04cdfa9352 req_err(1125717067) unknown_error : normal
4:05:44 PM dev_db.1  |      [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_req
4:05:44 PM dev_db.1  |  >  uest_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]

4:08:09 PM dev_web.1 |  Program node middleware.js exited with code null
4:08:09 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:08:09 PM dev_web.1 |  not monitoring changes
4:08:10 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db
4:08:17 PM dev_db.1  |  [error] 2019-01-26T00:08:17.562625Z dev_env-couchdb@localhost <0.13974.22> 0908a8896c req_err(1125717067) unknown_error : normal
4:08:17 PM dev_db.1  |      [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_req
4:08:17 PM dev_db.1  |  >  uest_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]

4:16:32 PM dev_web.1 |  Program node middleware.js exited with code null
4:16:32 PM dev_web.1 |  Starting child process with 'node middleware.js'
4:16:32 PM dev_web.1 |  MONITORING CHANGES
4:16:32 PM dev_web.1 |  Listening on 4000, using backend http://localhost:4100/my-db

Each time you see "Program node middleware.js exited with code null" was me killing the middleware process. I think the pattern's pretty clear.

1. First restart shown (4:04:33) is ambiguous since the log doesn't include whether the previous run was monitoring or not, but note that that middleware instance — call it "Process-1" — does not monitor changes.
2. There is no error after Process-1 is killed (at 4:04:54) and Process-2 is started (again not monitoring changes).
3. There is no error after Process-2 is killed (at 4:05:15) and Process-3 is started. Note that Process-3 does monitor changes.
4. After Process-3 is killed (at 4:05:38), there is an error shortly after (at 4:05:44). The new Process-4 does monitor changes.
5. After Process-4 is killed (at 4:08:09) there is again an error shortly after (at 4:08:17). The new Process-5 does not monitor changes.
6. After Process-5 is killed (at 4:16:32) there was no error logged (not within five minutes anyway…).

Perhap's in the OP's case their client library is dropping its connection "too quickly" in the case of a 4xx response code from the server?

[natevw]

Hah, forget all that "Process-N" mumbo-jumbo. Here's an easy repro:

1. In one terminal: curl "http://localhost:5986/some-db/_changes?since=now&feed=continuous"
2. From another terminal, kill that curl process.

Doesn't seem to happen as quickly or reliably if simply Ctrl-C'ing curl, or when feed=longpoll but maybe the delay between the connection dropping and the error logging is just longer than I am patient in these cases. (After a few minutes I seem to get a pile of errors in my CouchDB log but by then I've forgotten what I was testing…)

[wohali]

Another repro on this: saw it when enabling maintenance mode on a node.

[vincnetas]

Also getting this error on 2.3.0 after upgrade

[error] 2019-02-14T09:43:19.449719Z couchdb@127.0.0.1 <0.21732.2> 98da3606d3 req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:23.700648Z couchdb@127.0.0.1 <0.1825.2> d9b3af3f17 req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:24.430878Z couchdb@127.0.0.1 <0.16651.1> 707829a6c5 req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:26.462755Z couchdb@127.0.0.1 <0.17367.1> 388d47a1f1 req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:26.551631Z couchdb@127.0.0.1 <0.4304.2> 7d1044c05c req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:27.180748Z couchdb@127.0.0.1 <0.17700.1> e34e436ed1 req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]
[error] 2019-02-14T09:43:27.262753Z couchdb@127.0.0.1 <0.4690.2> 8c27bdd1dd req_err(1125717067) unknown_error : normal
    [<<"chttpd:catch_error/3 L356">>,<<"chttpd:handle_req_after_auth/2 L322">>,<<"chttpd:process_request/1 L303">>,<<"chttpd:handle_request_int/1 L243">>,<<"mochiweb_http:headers/6 L128">>,<<"proc_lib:init_p_do_apply/3 L247">>]

Using single node setup, with >300K DB's. Disabled cookie authentication, but still getting these errors.

allow_persistent_cookies = false
authentication_handlers = {couch_httpd_auth, default_authentication_handler}

[sergey-safarov]

Looks as this related to disk speed and request rate.
After disk data is cached into disk memory, issue "chttpd:handle_req_after_auth/2 L322" goes away.

Will make same test on SSD disk

[sergey-safarov]

On SSD disk i not have more error like

chttpd:handle_req_after_auth/2 L322

Looks as issue related to disk performance.

[vincnetas]

We have this issue on SSD's (as mentioned in comment 20 days ago)