Port is missing from log messages

[pmishev]

Summary of problem or feature request

I can see that in v.7 the port has disappeared from the host. After further digging I see it's been specifically requested and fixed in #548 & #782

Perhaps it is a valid use case (although I don't really understand it), but the change seems to be causing problems elsewhere - now the port is missing from the log messages too.

Code snippet of problem

Here is an example of what is sent to the logger now:

array(8) {
  ["message"]=>
  string(66) "curl -XDELETE 'http://127.0.0.1/sineflow-esb-test-bar?pretty=true'"
  ["context"]=>
  array(0) {
  }
  ["level"]=>
  int(200)
  ["level_name"]=>
  string(4) "INFO"
  ["channel"]=>
  string(10) "sfes_trace"
  ["datetime"]=>
  object(DateTime)#108 (3) {
    ["date"]=>
    string(26) "2019-08-03 12:53:10.801795"
    ["timezone_type"]=>
    int(3)
    ["timezone"]=>
    string(15) "Europe/Helsinki"
  }
  ["extra"]=>
  array(1) {
    ["backtrace"]=>
    NULL
  }
  ["formatted"]=>
  string(112) "[2019-08-03 12:53:10] sfes_trace.INFO: curl -XDELETE 'http://127.0.0.1/sineflow-esb-test-bar?pretty=true' [] []
"
}
array(8) {
  ["message"]=>
  string(9) "Response:"
  ["context"]=>
  array(5) {
    ["response"]=>
    array(1) {
      ["acknowledged"]=>
      bool(true)
    }
    ["method"]=>
    string(6) "DELETE"
    ["uri"]=>
    string(38) "http://127.0.0.1/sineflow-esb-test-bar"
    ["HTTP code"]=>
    int(200)
    ["duration"]=>
    float(0.026726)
  }
  ["level"]=>
  int(100)
  ["level_name"]=>
  string(5) "DEBUG"
  ["channel"]=>
  string(10) "sfes_trace"
  ["datetime"]=>
  object(DateTime)#111 (3) {
    ["date"]=>
    string(26) "2019-08-03 12:53:10.802988"
    ["timezone_type"]=>
    int(3)
    ["timezone"]=>
    string(15) "Europe/Helsinki"
  }
  ["extra"]=>
  array(1) {
    ["backtrace"]=>
    NULL
  }
  ["formatted"]=>
  string(189) "[2019-08-03 12:53:10] sfes_trace.DEBUG: Response: {"response":{"acknowledged":true},"method":"DELETE","uri":"http://127.0.0.1/sineflow-esb-test-bar","HTTP code":200,"duration":0.026726} []
"
}

Based on this information, I should be able to type in the terminal:

curl -XDELETE 'http://127.0.0.1/sineflow-esb-test-bar?pretty=true'

But of course this doesn't work, as it's trying to reach port 80, instead of 9200

[andrewnclark]

Working on something for this, the port information is available in the response. I need to modify the method that generates theformatted value in the above log so that it takes note of the port and write a test or two. Should have something for you to look at it the next couple days.

[ezimuel]

@andrewnclark thanks, I look forward to your PR. When I merged #782 I didn't notice the change in the log. We need to be sure to provide a unit test for that.

[pmishev]

Do we have any progress on this?

[ezimuel]

@pmishev I just sent this PR #950 to add the port in the log message. Basically, the $response['transfer_stats'] (here) contains many information related to the HTTP request. I just added the port in log success or log fail.

[lionslair]

I have had to roll this back to the previous version. AWS elastic search does not return this parameter. I get

ErrorException: Undefined index: primary_port in

The element is not present in
$response['transfer_stats']['primary_port']

https://github.com/elastic/elasticsearch-php/pull/950/files#diff-1b0215334399d80759820e3229367adfR377

[ezimuel]

@lionslair can you var_dump($response) in Connection::logRequestFail()? Thanks!

[lionslair]

Will do some point today and post. Have to switch my local env to use the aws and do the dump.

[lionslair]

I am still on the rolled back version but this is the dump from the fail. But I think this was because my local host wont connect to the remote now.
array:8 [ "transfer_stats" => array:39 [ "url" => "AWS host" "content_type" => null "http_code" => 0 "header_size" => 0 "request_size" => 0 "filetime" => -1 "ssl_verify_result" => 0 "redirect_count" => 0 "total_time" => 131.151398 "namelookup_time" => 0.103554 "connect_time" => 0.0 "pretransfer_time" => 0.0 "size_upload" => 0.0 "size_download" => 0.0 "speed_download" => 0.0 "speed_upload" => 0.0 "download_content_length" => -1.0 "upload_content_length" => -1.0 "starttransfer_time" => 0.0 "redirect_time" => 0.0 "redirect_url" => "" "primary_ip" => "" "certinfo" => [] "primary_port" => 0 "local_ip" => "" "local_port" => 0 "http_version" => 0 "protocol" => 0 "ssl_verifyresult" => 0 "scheme" => "" "appconnect_time_us" => 0 "connect_time_us" => 0 "namelookup_time_us" => 103554 "pretransfer_time_us" => 0 "redirect_time_us" => 0 "starttransfer_time_us" => 0 "total_time_us" => 131151398 "error" => "Failed to connect to vpc-es-staging-lqvf6axulg25mn2zvr2d33f6gy.ap-southeast-2.es.amazonaws.com port 443: Operation timed out" "errno" => 7 ] "curl" => array:2 [ "error" => "Failed to connect to {host} port 443: Operation timed out" "errno" => 7 ] "effective_url" => "{host}" "status" => null "reason" => null "body" => null "headers" => [] "error" => ConnectException {#2275 #message: "cURL error 7: Failed to connect to host port 443: Operation timed out" #code: 0 #file: "/var/www/q/vendor/guzzlehttp/ringphp/src/Client/CurlFactory.php" #line: 126 trace: { /var/www/q/vendor/guzzlehttp/ringphp/src/Client/CurlFactory.php:126 { › && isset($connectionErrors[$response['curl']['errno']]) › ? new ConnectException($message) › : new RingException($message); } /var/www/q/vendor/guzzlehttp/ringphp/src/Client/CurlFactory.php:91 { › return !empty($response['curl']['errno']) || !isset($response['status']) › ? self::createErrorResponse($handler, $request, $response) › : $response; arguments: { $handler: array:2 [ …2] $request: array:6 [ …6] $response: array:3 [ …3] } } /var/www/q/vendor/guzzlehttp/ringphp/src/Client/CurlHandler.php:96 { › › return CurlFactory::createResponse([$this, '_invokeAsArray'], $request, $response, $hd, $bd); › } arguments: { $handler: array:2 [ …2] $request: array:6 [ …6] $response: array:3 [ …3] $headers: [] $body: stream resource @1482 … } } /var/www/q/vendor/guzzlehttp/ringphp/src/Client/CurlHandler.php:68 { › return new CompletedFutureArray( › $this->_invokeAsArray($request) › ); arguments: { $request: array:6 [ …6] } } /var/www/q/vendor/guzzlehttp/ringphp/src/Client/Middleware.php:30 { › return empty($request['client']['future']) › ? $default($request) › : $future($request); arguments: { $request: array:6 [ …6] } } /var/www/q/vendor/elasticsearch/elasticsearch/src/Elasticsearch/Connections/Connection.php:243 { › // Send the request using the wrapped handler. › $response = Core::proxy($handler($request), function ($response) use ($connection, $transport, $request, $options) { › arguments: { array:6 [ …6] } } /var/www/q/vendor/elasticsearch/elasticsearch/src/Elasticsearch/Connections/Connection.php:220 { › $handler = $this->handler; › $future = $handler($request, $this, $transport, $options); › arguments: { array:6 [ …6] Connection {#2238 …} Transport {#2245 …} [] } } /var/www/q/vendor/elasticsearch/elasticsearch/src/Elasticsearch/Transport.php:105 { › $future = $connection->performRequest( › $method, › $uri, arguments: { $method: "POST" $uri: "/8ed40b1c-6288-415a-b8f2-0efb758ffae3-media/media/19" $params: [] $body: "{"id":19,"model_id":"6","model_type":"App\\Asset","collection_name":"image","name":"Screenshot from 2019-10-07 11-12-00","asset_name":null,"file_name":"2sWdjn4o9MMQYWZZBZkgXxtxkrQE0qa4E58FXYA1.png","mime_type":"image\/png","disk":"tenant","size":293300,"license_expires_at":null,"created_at":"2019-10-08T08:34:14.000000Z","updated_at":"2019-10-08T08:34:14.000000Z","deleted_at":null,"width":1920,"client":"1","height":1200,"bitrate":"","duration":"","has_audio":"","resolution":"72x72","description":"","encoding_format":"png","video_frame_rate":"","video_frame_size":"","original_filename":"Screenshot from 2019-10-07 11-12-00.png","thumb":true}" $options: [] $transport: Transport {#2245 …} } } /var/www/q/vendor/elasticsearch/elasticsearch/src/Elasticsearch/Client.php:1779 { › $endpoint->getBody(), › $endpoint->getOptions() › ); arguments: { $method: "POST" $uri: "/8ed40b1c-6288-415a-b8f2-0efb758ffae3-media/media/19" $params: [] $body: array:27 [ …27] $options: [] } } /var/www/q/vendor/elasticsearch/elasticsearch/src/Elasticsearch/Client.php:936 { › › return $this->performRequest($endpoint); › } arguments: { $endpoint: Index {#2258 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php:239 { › › return $instance->$method(...$args); › } arguments: { $params: [] } } /var/www/q/vendor/babenkoivan/scout-elasticsearch-driver/src/Indexers/SingleIndexer.php:44 { › › ElasticClient::index($payload->get()); › }); arguments: { $method: "index" $args: array:1 [ …1] } } /var/www/q/vendor/laravel/framework/src/Illuminate/Support/Traits/EnumeratesValues.php:176 { › foreach ($this as $key => $item) { › if ($callback($item, $key) === false) { › break; arguments: { Media {#2168 …} 0 } } /var/www/q/vendor/babenkoivan/scout-elasticsearch-driver/src/Indexers/SingleIndexer.php:45 { › ElasticClient::index($payload->get()); › }); › } arguments: { $callback: Closure {#2144 …} } } /var/www/q/app/Crowdco/Elasticsearch/Indexers/SingleIndexer.php:14 { › { › parent::update($models); › arguments: { $models: Collection {#2167 …} } } /var/www/q/vendor/babenkoivan/scout-elasticsearch-driver/src/ElasticEngine.php:80 { › ->indexer › ->update($models); › } arguments: { $models: Collection {#2167 …} } } /var/www/q/vendor/laravel/scout/src/Jobs/MakeSearchable.php:42 { › › $this->models->first()->searchableUsing()->update($this->models); › } arguments: { $models: Collection {#2167 …} } } Laravel\Scout\Jobs\MakeSearchable->handle() {} /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:32 { › return call_user_func_array( › $callback, static::getMethodDependencies($container, $callback, $parameters) › ); arguments: { $function_name: array:2 [ …2] $parameters: [] } } /var/www/q/vendor/laravel/framework/src/Illuminate/Support/helpers.php:522 { › { › return $value instanceof Closure ? $value() : $value; › } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:90 { › › return value($default); › } arguments: { $value: Closure {#2030 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:34 { › ); › }); › } arguments: { $container: Application {#4 …} $callback: array:2 [ …2] $default: Closure {#2030 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/Container.php:591 { › { › return BoundMethod::call($this, $callback, $parameters, $defaultMethod); › } arguments: { $container: Application {#4 …} $callback: array:2 [ …2] $parameters: [] $defaultMethod: null } } /var/www/q/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php:94 { › $callback = function ($command) { › return $this->container->call([$command, 'handle']); › }; arguments: { $callback: array:2 [ …2] } } /var/www/q/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php:130 { › try { › return $destination($passable); › } catch (Exception $e) { arguments: { MakeSearchable {#2124 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php:105 { › › return $pipeline($this->passable); › } arguments: { MakeSearchable {#2124 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php:98 { › › return $this->pipeline->send($command)->through($this->pipes)->then($callback); › } arguments: { $destination: Closure {#2147 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php:83 { › return $this->dispatcher->dispatchNow( › $command, $this->resolveHandler($job, $command) › ); arguments: { $command: MakeSearchable {#2124 …} $handler: false } } /var/www/q/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php:130 { › try { › return $destination($passable); › } catch (Exception $e) { arguments: { MakeSearchable {#2124 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php:105 { › › return $pipeline($this->passable); › } arguments: { MakeSearchable {#2124 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php:85 { › ); › }); › } arguments: { $destination: Closure {#2148 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php:59 { › › $this->dispatchThroughMiddleware($job, $command); › arguments: { $job: RedisJob {#2041 …} $command: MakeSearchable {#2124 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php:88 { › › ($this->instance = $this->resolve($class))->{$method}($this, $payload['data']); › } arguments: { $job: RedisJob {#2041 …} $data: array:2 [ …2] } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:348 { › // proper events will be fired to let any listeners know this job has finished. › $job->fire(); › } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:294 { › try { › return $this->process($connectionName, $job, $options); › } catch (Exception $e) { arguments: { $connectionName: "redis" $job: RedisJob {#2041 …} $options: WorkerOptions {#2037 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:129 { › if ($job) { › $this->runJob($job, $connectionName, $options); › } else { arguments: { $job: RedisJob {#2041 …} $connectionName: "redis" $options: WorkerOptions {#2037 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php:112 { › return $this->worker->{$this->option('once') ? 'runNextJob' : 'daemon'}( › $connection, $queue, $this->gatherWorkerOptions() › ); arguments: { $connectionName: "redis" $queue: "q-scout" $options: WorkerOptions {#2037 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php:96 { › $this->runWorker( › $connection, $queue › ); arguments: { $connection: "redis" $queue: "q-scout" } } /var/www/q/vendor/laravel/horizon/src/Console/WorkCommand.php:46 { › › parent::handle(); › } } Laravel\Horizon\Console\WorkCommand->handle() {} /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:32 { › return call_user_func_array( › $callback, static::getMethodDependencies($container, $callback, $parameters) › ); arguments: { $function_name: array:2 [ …2] $parameters: [] } } /var/www/q/vendor/laravel/framework/src/Illuminate/Support/helpers.php:522 { › { › return $value instanceof Closure ? $value() : $value; › } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:90 { › › return value($default); › } arguments: { $value: Closure {#2030 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php:34 { › ); › }); › } arguments: { $container: Application {#4 …} $callback: array:2 [ …2] $default: Closure {#2030 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Container/Container.php:591 { › { › return BoundMethod::call($this, $callback, $parameters, $defaultMethod); › } arguments: { $container: Application {#4 …} $callback: array:2 [ …2] $parameters: [] $defaultMethod: null } } /var/www/q/vendor/laravel/framework/src/Illuminate/Console/Command.php:202 { › { › return $this->laravel->call([$this, 'handle']); › } arguments: { $callback: array:2 [ …2] } } /var/www/q/vendor/symfony/console/Command/Command.php:255 { › } else { › $statusCode = $this->execute($input, $output); › } arguments: { $input: ArgvInput {#34 …} $output: OutputStyle {#2031 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Console/Command.php:189 { › return parent::run( › $this->input = $input, $this->output › ); arguments: { $input: ArgvInput {#34 …} $output: OutputStyle {#2031 …} } } /var/www/q/vendor/symfony/console/Application.php:915 { › if (null === $this->dispatcher) { › return $command->run($input, $output); › } arguments: { $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } /var/www/q/vendor/symfony/console/Application.php:272 { › $this->runningCommand = $command; › $exitCode = $this->doRunCommand($command, $input, $output); › $this->runningCommand = null; arguments: { $command: WorkCommand {#1417 …} $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } /var/www/q/vendor/symfony/console/Application.php:148 { › try { › $exitCode = $this->doRun($input, $output); › } catch (\Exception $e) { arguments: { $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Console/Application.php:90 { › › $exitCode = parent::run($input, $output); › arguments: { $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } /var/www/q/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php:131 { › › return $this->getArtisan()->run($input, $output); › } catch (Exception $e) { arguments: { $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } /var/www/q/artisan:37 { › $input = new Symfony\Component\Console\Input\ArgvInput, › new Symfony\Component\Console\Output\ConsoleOutput › ); arguments: { $input: ArgvInput {#34 …} $output: ConsoleOutput {#32 …} } } } } ]

[cyrnetix]

Just upgraded elasticsearch to 7.5.1 and vendor 7.4.1. This casued the same issue. This field is not included in the response and causes notices.

[limingjundawn]

Just upgraded elasticsearch to 7.5.1 and vendor 7.4.1. This casued the same issue. This field is not included in the response and causes notices.

I have a same problem. curl can not getprimary_port. And I found something, like this https://curl.haxx.se/libcurl/c/CURLINFO_PRIMARY_PORT.html

It is say PRIMARY_POR Added in 7.21.0, so I update curl version to last， but it can not working

[ezimuel]

@limingjundawn thanks for the update, I'll investigate more on that.

[cyrnetix]

Just tested with curl 7.60 on CentOS 6 and en 7.58 on Ubuntu 18.4 and both don't return this field and are causing notices.

[limingjundawn]

@cyrnetix I find the way to solve this problem.
1.I update curl version to last
2.I compile php curl extension again. then it working now

[lionslair]

What is the last curl version?

[lionslair]

Why can't
$response['transfer_stats']['primary_port']
just be wrapped in isset
'port' => isset($response['transfer_stats']['primary_port']) ? $response['transfer_stats']['primary_port'] : null,

[ezimuel]

@lionslair the last version is 7.68.0, see curl release table.
I already applied your suggestion in #986 with this code.
I'll release this soon, thanks.

[cyrnetix]

That would be nice, not everyone is able to upgrade the curl version on their server.

[lionslair]

We just used this and updated our composer file for the mean time
https://github.com/crowdco-developer/elasticsearch-php/releases/tag/7.3.0

[erikvanderschaaf]

@lionslair the last version is 7.68.0, see curl release table.
I already applied your suggestion in #986 with this code.
I'll release this soon, thanks.

Any estimate on the release of this fix?

[ezimuel]

This has been fixed with 7.5.1 release

[pmishev]

I've now had to come back to this after some time and the issue doesn't seem to be fixed:

        $tracer = new Logger('es');
        $tracer->pushHandler(new StreamHandler('trace.log', Logger::DEBUG));

        $clientBuilder = ClientBuilder::create();
        $clientBuilder->setHosts(['192.168.56.115:9200']);
        $clientBuilder->setTracer($tracer);

        $client = $clientBuilder->build();
        $res = $client->indices()->getAlias(['name' => 'blah']);

trace.log contains:

[2021-03-09 15:18:54] es.INFO: curl -XGET 'http://192.168.56.115/_alias/blah?pretty=true' [] []
[2021-03-09 15:18:54] es.DEBUG: Response: {"response":{"transfer_stats":{"url":"http://192.168.56.115/_alias/blah","content_type":"application/json; charset=UTF-8","http_code":404,"header_size":93,"request_size":285,"filetime":-1,"ssl_verify_result":0,"redirect_count":0,"total_time":0.00455,"namelookup_time":5.2e-5,"connect_time":0.000904,"pretransfer_time":0.00118,"size_upload":0,"size_download":45,"speed_download":11250,"speed_upload":0,"download_content_length":45,"upload_content_length":-1,"starttransfer_time":0.004478,"redirect_time":0,"redirect_url":"","primary_ip":"192.168.56.115","certinfo":[],"primary_port":9200,"local_ip":"192.168.56.111","local_port":59218,"http_version":2,"protocol":1,"ssl_verifyresult":0,"scheme":"HTTP","error":"","errno":0},"curl":{"error":"","errno":0},"effective_url":"http://192.168.56.115/_alias/blah","headers":{"content-type":["application/json; charset=UTF-8"],"content-length":["45"]},"version":"1.1","status":404,"reason":"Not Found","body":"{\"error\":\"alias [blah] missing\",\"status\":404}"},"method":"GET","uri":"http://192.168.56.115/_alias/blah","HTTP code":404,"duration":0.00455} []

Clearly the port is still missing from the URL. It should be:
http://192.168.56.115:9200/_alias/blah
not http://192.168.56.115/_alias/blah

This is on 7.11.0.
Am I missing something here?