couchdb-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Curt Arnold (JIRA)" <j...@apache.org>
Subject [jira] Commented: (COUCHDB-394) Intermittent HTTP 500 errors on queries, no useful diagnostics
Date Mon, 27 Jul 2009 18:19:15 GMT

    [ https://issues.apache.org/jira/browse/COUCHDB-394?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12735695#action_12735695
] 

Curt Arnold commented on COUCHDB-394:
-------------------------------------

I cloned my application and made the following modification to hopefully provide more diagnostics
of the underlying problem.

===================================================================
--- src/mochiweb/mochiweb_request.erl   (revision 798196)
+++ src/mochiweb/mochiweb_request.erl   (working copy)
@@ -121,6 +121,8 @@
     case gen_tcp:send(Socket, Data) of
         ok ->
             ok;
+        { error, Reason } ->
+            exit(Reason);
         _ ->
             exit(normal)
     end.

Was finally able to trigger the error and had the following in the log:

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] 'POST' /loaded/_design/query/_view/byURI?include_docs=true
{1,1}
Headers: [{'Accept',"text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"},
          {'Cache-Control',"no-cache"},
          {'Connection',"keep-alive"},
          {'Content-Length',"1373"},
          {'Content-Type',"application/x-www-form-urlencoded"},
          {'Host',"localhost:5984"},
          {'Pragma',"no-cache"},
          {'User-Agent',"Java/1.6.0_0"}]

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] request_group {Pid, Seq} {<0.119.0>,4709}

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O284">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O209">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"d6490a8694d19768347dab5c62969b33">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O182">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O187">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O229">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O20">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O248">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O225">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O2">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O204">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O201">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O133">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O32">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O12">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O251">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O192">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O174">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O290">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O238">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O197">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#acme">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O232">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O74">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Include Doc: <<"http://www.example.com/2009/03/schema#O114">>
nil

[Mon, 27 Jul 2009 16:45:55 GMT] [error] [<0.1162.0>] Uncaught error in HTTP request:
{exit,closed}

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] Stacktrace: [{mochiweb_request,send,2},
             {couch_httpd,send_chunk,2},
             {couch_httpd_view,design_doc_view,5},
             {couch_httpd_db,do_db_req,2},
             {couch_httpd,handle_request,5},
             {mochiweb_http,headers,5},
             {proc_lib,init_p,5}]

[Mon, 27 Jul 2009 16:45:55 GMT] [debug] [<0.1162.0>] httpd 500 error response:
 {"error":"unknown_error","reason":"closed"}


[Mon, 27 Jul 2009 16:45:55 GMT] [error] [<0.1162.0>] {error_report,<0.21.0>,
    {<0.1162.0>,crash_report,
     [[{pid,<0.1162.0>},
       {registered_name,[]},
       {error_info,
           {exit,enotconn,
               [{mochiweb_request,send,2},
                {mochiweb_request,start_raw_response,2},
                {mochiweb_request,respond,2},
                {couch_httpd,send_response,4},
                {couch_httpd,handle_request,5},
                {mochiweb_http,headers,5},
                {proc_lib,init_p,5}]}},
       {initial_call,
           {mochiweb_socket_server,acceptor_loop,
               [{<0.54.0>,#Port<0.148>,#Fun<mochiweb_http.1.81679042>}]}},
       {ancestors,
           [couch_httpd,couch_secondary_services,couch_server_sup,
            <0.1.0>]},
       {messages,[]},
       {links,[#Port<0.309>,<0.54.0>,#Port<0.308>]},
       {dictionary,
           [{mochiweb_request_body,
                <<"{\"keys\":[\"http://www.example.com/2009/03/schema#O284\",\"http://www.example.com/2009/03/schema#O209\",\"urn:uuid:d6490a86-94d1-9768-347d-ab5c62969b33\",\"http://www.example.com/2009/03/schema#O182\",\"http://www.example.com/2009/03/schema#O187\",\"http://www.example.com/2009/03/schema#O229\",\"http://www.example.com/2009/03/schema#O20\",\"http://www.example.com/2009/03/schema#O248\",\"http://www.example.com/2009/03/schema#O225\",\"http://www.example.com/2009/03/schema#O2\",\"http://www.example.com/2009/03/schema#O204\",\"http://www.example.com/2009/03/schema#O201\",\"http://www.example.com/2009/03/schema#O133\",\"http://www.example.com/2009/03/schema#O32\",\"http://www.example.com/2009/03/schema#O12\",\"http://www.example.com/2009/03/schema#O251\",\"http://www.example.com/2009/03/schema#O192\",\"http://www.example.com/2009/03/schema#O174\",\"http://www.example.com/2009/03/schema#O290\",\"http://www.example.com/2009/03/schema#O238\",\"http://www.example.com/2009/03/schema#O197\",\"http://www.example.com/2009/03/schema#acme\",\"http://www.example.com/2009/03/schema#O232\",\"http://www.example.com/2009/03/schema#O74\",\"http://www.example.com/2009/03/schema#O114\"]}">>},
            {mochiweb_request_qs,[{"include_docs","true"}]},
            {mochiweb_request_recv,true},
            {jsonp,undefined},
            {couch_drv_port,#Port<0.309>}]},
       {trap_exit,false},
       {status,running},
       {heap_size,2584},
       {stack_size,23},
       {reductions,87159}],
      []]}}

[Mon, 27 Jul 2009 16:45:55 GMT] [error] [<0.54.0>] {error_report,<0.21.0>,
              {<0.54.0>,std_error,
               {mochiweb_socket_server,235,{child_error,enotconn}}}}

The corresponding code on the client side is:

	new JSONObject(new JSONTokener(new BufferedReader(new InputStreamReader(connection.getInputStream(),
"utf-8"))));

In this particular failure, both the client and CouchDB are on the same machine, so it is
unlikely a problem with a network intermediary.  The list of fetched documents matches the
expected response to the query (in this particular instance, document IDs have a one-to-one
correspondency with keys, though that is not generally the case).   Since all the documents
were fetched and the time between request and failure was less than a second, a timeout seems
unlikely.

If there was a problem with the decoding or parsing, it might have prematurely closed the
socket, resulting in the error.

Any thoughts?





> Intermittent HTTP 500 errors on queries, no useful diagnostics
> --------------------------------------------------------------
>
>                 Key: COUCHDB-394
>                 URL: https://issues.apache.org/jira/browse/COUCHDB-394
>             Project: CouchDB
>          Issue Type: Bug
>          Components: HTTP Interface
>    Affects Versions: 0.10
>         Environment: Ubuntu 8.10 on x386 on Amazon Web Services VM
>            Reporter: Curt Arnold
>
> Originally raised on user@couchdb.apache.org on 2009-06-16, but no resolution.  Original
message follows later.
> Analysis: seems like there is a failure during the call to gen_tcp:send, a connection
dropped or something like that, however the calling code in mochiweb_request:send appears
to discard the reason returned by gen_tcp:send leaving a user with no clue of the underlying
problem.
> Here is Mochiweb_request:send
> send(Data) ->
>     case gen_tcp:send(Socket, Data) of
>         ok ->
>             ok;
>         _ ->
>             exit(normal)
>     end.
> In the case of a non ok return from gen_tcp:send, exit(normal) is called which is connected
with the log file in the original message.  It would seem much more helpful if the recent
included in the return value from gen_tcp:send was passed to the exit/1 function.
> Actually, a different function appears in the original log file.  I was looking at a
slightly different entry in a different log file, but I think the analysis holds.
> Different log snippet:
> [Wed, 27 May 2009 00:39:00 GMT] [info] [<0.3318.13>] 127.0.0.1 - - 'GET' /default/_design/query/_view/byURI?include_docs=true;key=...
200
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3318.13>] 'GET' /default/_design/query/_view/byURI?include_docs=true;key=..
{1,
>                                                                                     
                                1}
> Headers: [{'Accept',"text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"},
>           {'Connection',"keep-alive"},
>           {'Host',"localhost:5984"},
>           {'User-Agent',"Java/1.6.0_0"}]
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3318.13>] request_group {Pid, Seq}
{<0.3872.0>,1890}
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3318.13>] Include Doc: <<"...">>
nil
> [Wed, 27 May 2009 00:39:00 GMT] [error] [<0.3318.13>] Uncaught error in HTTP request:
{exit,normal}
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3318.13>] Stacktrace: [{mochiweb_request,send,2},
>              {couch_httpd,send_chunk,2},
>              {couch_httpd_view,design_doc_view,5},
>              {couch_httpd_db,do_db_req,2},
>              {couch_httpd,handle_request,5},
>              {mochiweb_http,headers,5},
>              {proc_lib,init_p,5}]
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3332.13>] 'GET' /default/_design/query/_view/forSubject?include_docs=true;key=[]
{1,
>                                                                                     
                                                                                         
   1}
> Headers: [{'Accept',"text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"},
>           {'Connection',"keep-alive"},
>           {'Host',"localhost:5984"},
>           {'User-Agent',"Java/1.6.0_0"}]
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3318.13>] httpd 500 error response:
>  {"error":"unknown_error","reason":"normal"}
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3332.13>] request_group {Pid, Seq}
{<0.3872.0>,1890}
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3332.13>] Include Doc: <<"...">>
nil
> [Wed, 27 May 2009 00:39:00 GMT] [debug] [<0.3332.13>] Include Doc: <<"...">>
nil
> ------
> Original message:
> I've been seeing HTTP 500 failures from time to time with a fairly  
> recent snapshot build ("0.10.0a777361") from the SVN.  The actual keys  
> have been omitted, however the queries have been working for a long  
> time and the keys are valid and return the right data most of the time.
> Any clues what might be happening?
> [Thu, 18 Jun 2009 01:22:59 GMT] [debug] [<0.1178.84>] 'POST' /loaded/ 
> _design/query/_view/byURI?include_docs=true {1,1}
> Headers: [{'Accept',"*/*"},
>           {'Accept-Encoding',"gzip, deflate"},
>           {'Accept-Language',"en-us"},
>           {'Cache-Control',"no-cache"},
>           {'Connection',"Keep-Alive"},
>           {'Content-Length',"537"},
>           {'Content-Type',"text/plain; charset=utf-8"},
>           {'Cookie',"x-auto-16=m%3Asize%7Cf%3A235.0"},
>           {'Host',"localhost:5984"},
>           {'Referer',"http://localhost:8888/browser/hosted.html? 
> browser"},
>           {'User-Agent',"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT  
> 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR  
> 3.5.30729; .NET CLR 1.1.4322)"}]
> [Thu, 18 Jun 2009 01:22:59 GMT] [debug] [<0.1180.84>] 'GET' /loaded/ 
> _design/query/_view/forSubject?include_docs=true;;key=[omitted] {1,
>                                                                                     
                                                                                         
                         1 
> }
> Headers: [{'Accept',"*/*"},
>           {'Accept-Encoding',"gzip, deflate"},
>           {'Accept-Language',"en-us"},
>           {'Cache-Control',"no-cache"},
>           {'Connection',"Keep-Alive"},
>           {'Cookie',"x-auto-16=m%3Asize%7Cf%3A235.0"},
>           {'Host',"localhost:5984"},
>           {'Referer',"http://localhost:8888/browser/hosted.html? 
> browser"},
>           {'User-Agent',"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT  
> 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR  
> 3.5.30729; .NET CLR 1.1.4322)"}]
> [Thu, 18 Jun 2009 01:22:59 GMT] [debug] [<0.1180.84>] request_group  
> {Pid, Seq} {<0.15823.64>,4485}
> [Thu, 18 Jun 2009 01:22:59 GMT] [info] [<0.1180.84>] 127.0.0.1 - -  
> 'GET' /loaded/_design/query/_view/forSubject? 
> include_docs=true;;key=[omitted] 200
> [Thu, 18 Jun 2009 01:22:59 GMT] [debug] [<0.1180.84>] 'GET' /loaded/ 
> _design/query/_view/byURI?include_docs=true;key=[omitted] {1,
>                                                                                     
                                           1 
> }
> Headers: [{'Accept',"*/*"},
>           {'Accept-Encoding',"gzip, deflate"},
>           {'Accept-Language',"en-us"},
>           {'Cache-Control',"no-cache"},
>           {'Connection',"Keep-Alive"},
>           {'Cookie',"x-auto-16=m%3Asize%7Cf%3A235.0"},
>           {'Host',"localhost:5984"},
>           {'If-None-Match',"\"60FWBA3D7UUZI9NSMR4PS9VM4\""},
>           {'Referer',"http://localhost:8888/browser/hosted.html? 
> browser"},
>           {'User-Agent',"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT  
> 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR  
> 3.5.30729; .NET CLR 1.1.4322)"}]
> [Thu, 18 Jun 2009 01:22:59 GMT] [debug] [<0.1180.84>] request_group  
> {Pid, Seq} {<0.15823.64>,4485}
> [Thu, 18 Jun 2009 01:22:59 GMT] [info] [<0.1180.84>] 127.0.0.1 - -  
> 'GET' /loaded/_design/query/_view/byURI? 
> include_docs=true;key=[omitted] 304
> [Thu, 18 Jun 2009 01:23:09 GMT] [error] [<0.1178.84>] Uncaught error  
> in HTTP request: {exit,normal}
> [Thu, 18 Jun 2009 01:23:09 GMT] [debug] [<0.1178.84>] Stacktrace:  
> [{mochiweb_request,recv,3},
>              {mochiweb_request,stream_unchunked_body,5},
>              {mochiweb_request,recv_body,2},
>              {couch_httpd,json_body,1},
>              {couch_httpd,json_body_obj,1},
>              {couch_httpd_view,handle_view_req,2},
>              {couch_httpd_db,do_db_req,2},
>              {couch_httpd,handle_request,5}]
> [Thu, 18 Jun 2009 01:23:09 GMT] [debug] [<0.1178.84>] httpd 500 error  
> response:
> {"error":"unknown_error","reason":"normal"}
> [Thu, 18 Jun 2009 01:23:09 GMT] [info] [<0.1178.84>] 127.0.0.1 - -  
> 'POST' /loaded/_design/query/_view/byURI?include_docs=true 500
> [Thu, 18 Jun 2009 01:23:20 GMT] [debug] [<0.1180.84>] 'GET' /loaded/ 
> _design/query/_view/forValue?key=[omitted] {1,
>                                                                                     
                                                                                         
                   1 
> }
> Headers: [{'Accept',"*/*"},
>           {'Accept-Encoding',"gzip, deflate"},
>           {'Accept-Language',"en-us"},
>           {'Connection',"Keep-Alive"},
>           {'Content-Type',"text/plain; charset=utf-8"},
>           {'Cookie',"x-auto-16=m%3Asize%7Cf%3A235.0"},
>           {'Host',"localhost:5984"},
>           {'If-None-Match',"\"60FWBA3D7UUZI9NSMR4PS9VM4\""},
>           {'Referer',"http://localhost:8888/browser/hosted.html? 
> browser"},
>           {'User-Agent',"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT  
> 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR  
> 3.5.30729; .NET CLR 1.1.4322)"}]
> [Thu, 18 Jun 2009 01:23:20 GMT] [debug] [<0.1180.84>] request_group  
> {Pid, Seq} {<0.15823.64>,4485}

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message