Error message text is "64"!

[timbunce]

We're testing out S:ES 1.20 plus all-latest prereqs and encountered an odd problem.
Everything seems to work fine, but if there is an error then the error message text is just 64!

For example:

[Request] ** [http://mls-es-stag-ddc.tigerlead.local:9200]-[0] 64, called from sub Search::Elasticsearch::Transport::try {...} at /home/tigerstage/trunk_1506041752/cpan/cpan-5.020/lib/perl5/Try/Tiny.pm line 81. With vars: {'request' => {'method' => 'GET','body' => {'from' => 0,'query' => {'constant_score' => {'filter' => {'and' => [{'terms' => {'mls_area_id' => [902146,901799,902027,902132,902933,902554,902896,901817,901810,901938,901989,901770,902583,902337,902170,901646,902442,902657,902946,903058,902401,903118,901748,902807,901884,901974,903013,902254,902710,903433,903133,901869,901873,902026,902065,903178,901864,901836,901725,901701,902987,901853,902463,902789,902645,902371,901728,901717,903031,903092,902815,902688,902427,901905,901716,902998,903057,902428,901706,902557,901762,903104,902929,902444,902191,903132,902953,902496,902925,901901,903056,902509,902636,902297,902842,901855,901894,903087,901882,902693,901765,902764,901775,902686,901719,902576,902718,903151,902500,902423,903086,902335,902273,901790,902462,902631,902911,902875,901802,903091,902242,903060,901995,902156,901903,901898,903082,902735,902894,901711,902323,901968,902961,902881,902142,902885,902999,902973,902861,902201,902075,902724,902927,903070,903068,902648,902397,902014,902339,903033,902721,903045,902291,905765,902660,902699,903119,901944,902029,902586,902499,902381,902990,902906,903185,901757,901872,902924,901768,902114,903146,902985,903089,902192,902979,902566,901689,902915,903081,902251,901832,901924,901861,902023,902059,902840,902623,902757,903153,901913,902743,902492,902746,902022,902908,902547,902497,902874,902282,901842,902344,903080,902517,902917,902817,902087,901926,902199,902848,902078,902951,901824,903035,902687,902349,902864,902316,902202,902507,902188,901657,903051,902571],'execution' => 'bool'}},{'geo_polygon' => {'address_location' => {'points' => [['-117.3994','33.98902'],['-117.59167','34.06642'],['-117.76195','33.97991'],['-117.91576','34.00724'],['-117.97069','33.97536'],['-118.01464','33.87052'],['-117.79491','33.83859'],['-117.89379','33.72901'],['-117.82238','33.72901'],['-117.77294','33.64674'],['-117.50927','33.56439'],['-117.51476','33.48654'],['-117.3994','33.43613'],['-117.31701','33.48196'],['-117.33349','33.62845'],['-117.21813','33.56439'],['-117.13024','33.66503'],['-117.14672','33.76555'],['-117.22362','33.81577'],['-117.26208','33.94347'],['-117.02587','33.88876'],['-116.56994','33.89788'],['-116.25133','33.71988'],['-116.16344','33.73358'],['-116.31725','33.77469'],['-116.58642','33.92979'],['-117.3994','33.98902']]}}},{'term' => {'mls_board_id' => 1312}},{'terms' => {'mls_boards_mls_type_id' => [5022,5182,5186]}},{'range' => {'images_count' => {'gte' => 1}}}]}}},'sort' => ['_score',{'price' => 'desc'},{'created_at' => 'desc'}],'fields' => ['_parent','_routing','_source'],'explain' => '','size' => 18},'qs' => {'version' => 1},'serialize' => 'std','path' => '/mls_fts_board_1312/mls_listing/_search','ignore' => [],'mime_type' => 'application/json'},'status_code' => 0}

For this application we're still using ES 0.90 (yes, I know!) so that might be a factor.

[clintongormley]

Would you prefer "42"? :)

I did some refactoring of error messages to handle the structured exceptions coming in v2, and I probably messed something up somewhere. Could you turn on trace logging to see the actual body that is returned for the above request? ie

$e=Search::Elasticsearch->new( trace_to => 'Stderr' )

[timbunce]

Of course! If you're going to provide an answer then it would obviously be the answer!

I forgot to mention I'm using Elastic::Model 0.50.

curl -XGET 'http://localhost:9200/mls_fts_board_925/mls_listing/_search?pretty=1&version=1' -d '
{
   "sort" : [
      "_score",
      {
         "created_at" : "desc"
      },
      {
         "created_at" : "desc"
      }
   ],
   "fields" : [
      "_parent",
      "_routing",
      "_source"
   ],
   "explain" : "",
   "query" : {
      "constant_score" : {
         "filter" : {
            "and" : [
               {
                  "terms" : {
                     "execution" : "bool",
                     "mls_area_id" : [
                        "489348",
                        "489379",
                        "489371",
                        "489333",
                        "489362",
                        "489368",
                        "489329",
                        "489343",
                        "489339",
                        "489332",
                        "489317",
                        "489327",
                        "489376",
                        "489325",
                        "489349",
                        "489316",
                        "489321",
                        "489374",
                        "489345",
                        "489380",
                        "489366",
                        "489328",
                        "489337",
                        "489323",
                        "489367",
                        "489357",
                        "489378",
                        "489377",
                        "489358",
                        "489335",
                        "489344",
                        "489331",
                        "489546",
                        "489346",
                        "489314"
                     ]
                  }
               },
               {
                  "geo_polygon" : {
                     "address_location" : {
                        "points" : [
                           [
                              -80.95022,
                              32.30283
                           ],
                           [
                              -80.97219,
                              32.24187
                           ],
                           [
                              -80.91932,
                              32.26104
                           ],
                           [
                              -80.92962,
                              32.21283
                           ],
                           [
                              -80.88018,
                              32.24013
                           ],
                           [
                              -80.88293,
                              32.19192
                           ],
                           [
                              -80.84379,
                              32.21399
                           ],
                           [
                              -80.84859,
                              32.16634
                           ],
                           [
                              -80.80671,
                              32.18552
                           ],
                           [
                              -80.79847,
                              32.13786
                           ],
                           [
                              -80.78542,
                              32.18204
                           ],
                           [
                              -80.75109,
                              32.17855
                           ],
                           [
                              -80.78268,
                              32.21399
                           ],
                           [
                              -80.74972,
                              32.22096
                           ],
                           [
                              -80.78748,
                              32.23432
                           ],
                           [
                              -80.75933,
                              32.25523
                           ],
                           [
                              -80.8122,
                              32.25988
                           ],
                           [
                              -80.7916,
                              32.30167
                           ],
                           [
                              -80.83623,
                              32.28194
                           ],
                           [
                              -80.85065,
                              32.29819
                           ],
                           [
                              -80.87125,
                              32.26046
                           ],
                           [
                              -80.87331,
                              32.32315
                           ],
                           [
                              -80.89048,
                              32.28716
                           ],
                           [
                              -80.89185,
                              32.33997
                           ],
                           [
                              -80.91314,
                              32.30109
                           ],
                           [
                              -80.92206,
                              32.33707
                           ],
                           [
                              -80.92206,
                              32.3098
                           ],
                           [
                              -80.93648,
                              32.31676
                           ],
                           [
                              -80.93786,
                              32.30167
                           ],
                           [
                              -80.95022,
                              32.30283
                           ]
                        ]
                     }
                  }
               },
               {
                  "term" : {
                     "mls_board_id" : "925"
                  }
               },
               {
                  "term" : {
                     "mls_boards_mls_type_id" : "3315"
                  }
               },
               {
                  "range" : {
                     "images_count" : {
                        "gte" : "1"
                     }
                  }
               }
            ]
         }
      }
   },
   "from" : 0,
   "size" : "18"
}
'

# ERROR: Search::Elasticsearch::Error::Request [http://mls-es-stag-ddc.tigerlead.local:9200]-[0] 64

If I copy-n-paste that curl command, and fix the hostname, then the request runs fine, repeatedly.

[clintongormley]

What I'm interested in is the response that ES sent, hence the trace logging

[timbunce]

Adding a -v to the curl shows

> GET /mls_fts_board_925/mls_listing/_search?pretty=1&version=1 HTTP/1.1
> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.16.2.3 Basic ECC zlib/1.2.3 libidn/1.18 libssh2/1.4.2
> Host: mls-es-stag-ddc.tigerlead.local:9200
> Accept: */*
> Content-Length: 6601
> Content-Type: application/x-www-form-urlencoded
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
< HTTP/1.1 200 OK
< Content-Type: application/json; charset=UTF-8
< Content-Length: 41934

Is that what you're after?

[clintongormley]

No, turn on trace logging as follows:

$e=Search::Elasticsearch->new( trace_to => 'Stderr' )

[timbunce]

I did. I pasted the output (curl ... plus # ERROR: ...) in the earlier comment.

[clintongormley]

That's it? Nothing in the body itself?

[timbunce]

Nope. Nothing.

[timbunce]

Per twitter DMs this seems to be a bug in Hijk handling of a particular case, so it returns an error, combined with a bug in the ES Hijk Cxn module in how it reports that error.

The Hijk error is Wasn't expecting a 0 byte response for http head. This shouldn't happen.
The write to ES is:

GET /mls_fts_board_925/mls_listing/_search?version=1 HTTP/1.1
Host: mls-es-stag-ddc.tigerlead.local
Content-Length: 1340
Content-Type: application/json

{"from":0,"query":{"constant_score":{"filter":{"and":[{"terms":{"execution":"bool","mls_area_id":["489348","489379","489371","489333","489362","489368","489329","489343","489339","489332","489317","489327","489376","489325","489349","489316","489321","489374","489345","489380","489366","489328","489337","489323","489367","489357","489378","489377","489358","489335","489344","489331","489546","489346","489314"]}},{"geo_polygon":{"address_location":{"points":[[-80.95022,32.30283],[-80.97219,32.24187],[-80.91932,32.26104],[-80.92962,32.21283],[-80.88018,32.24013],[-80.88293,32.19192],[-80.84379,32.21399],[-80.84859,32.16634],[-80.80671,32.18552],[-80.79847,32.13786],[-80.78542,32.18204],[-80.75109,32.17855],[-80.78268,32.21399],[-80.74972,32.22096],[-80.78748,32.23432],[-80.75933,32.25523],[-80.8122,32.25988],[-80.7916,32.30167],[-80.83623,32.28194],[-80.85065,32.29819],[-80.87125,32.26046],[-80.87331,32.32315],[-80.89048,32.28716],[-80.89185,32.33997],[-80.91314,32.30109],[-80.92206,32.33707],[-80.92206,32.3098],[-80.93648,32.31676],[-80.93786,32.30167],[-80.95022,32.30283]]}}},{"term":{"mls_board_id":"925"}},{"term":{"mls_boards_mls_type_id":"3315"}},{"range":{"images_count":{"gte":"1"}}}]}}},"fields":["_parent","_routing","_source"],"sort":["_score",{"created_at":"desc"},{"created_at":"desc"}],"explain":"","size":"18"}

This is different to the request sent by curl, for example it's missing the Expect: 100-continue and has a different Content-Type.

The POSIX::read in Hijk returns "0 but true" on the first call. So it seems that ES has closed the connection.

[clintongormley]

@timbunce In eg the NetCurl backend, we disable the Expect header and set the same content type, so the request should be the same as what is being sent via Hijk.

[timbunce]

I suspect the bug in Hijk is that it doesn't handle getting a 0 byte packet. That ought to be ignored.
Using the HTTPTiny backend seems to be working fine.

[timbunce]

I've opened a Hijk ticket for this.