CURL headers are overwritten in v0.15.1

[tot-ra]

Hola. Wanted to report this bug which blocks us actually. Using php 7.1

When I make curl request, datadog seems to intercept headers and rewrite them to its own In our case its host that is important

[tot-ra]

Setting DD_INTEGRATIONS_DISABLED=curl seems to help, still, quite unexpected & took a long time to debug

[fbaligant]

Confirming it is happening on PHP 7.1 on the latest 0.16.1 as well.

[labbati]

Hi @tot-ra and sorry for the late reply. We actually do intercept headers in order to add distributed tracing which is based on headers, too. What I guess is that some specific headers that are natively added by curl (and Host may be an example) is not properly merged into the final batch.

I bet that if you manually set an header (e.g. through set_opt or set_opts) this will be present instead.

Let we add this to our list to be addresses very soon.

[labbati]

hi @tot-ra I may need more info here as I have some hard times replicating the issue.

Here is what I am doing:

$ch = curl_init($url);
curl_setopt($ch, CURLOPT_RETURNTRANSFER, true);
curl_setopt($ch, CURLOPT_HTTPHEADER, [
    'Some-Header: preserved_value',
    'Host: api.v1',
]);
curl_exec($ch)

And here are the headers I get

{
  "headers": {
    "Accept": "*/*",
    "Host": "api.v1",
    "Some-Header": "preserved_value",
    "X-Datadog-Parent-Id": "6745010270449640555",
    "X-Datadog-Sampling-Priority": "1",
    "X-Datadog-Trace-Id": "6003981333121609853"
  }
}

Do you see anything in the curl request that I exec that notably differs from what you are doing?

This would be useful to recreate!

[fbaligant]

@labbati the code in our case:

function callHipayTokenizationApi(\payment\Hipay $hipayInstance, $token)
{
  $curl = curl_init();
  curl_setopt_array(
    $curl,
    [
      CURLOPT_URL => getHipayTokenizationEndpoint().'/'.$token.'?request_id=0',
      CURLOPT_USERPWD => getHipayApiCredentials($hipayInstance),
      CURLOPT_HTTPHEADER => ['Accept: application/json'],
      CURLOPT_RETURNTRANSFER => true,
      CURLOPT_FAILONERROR => false,
      CURLOPT_HEADER => false,
    ]
  );

  $error = false === ($result = curl_exec($curl));
  $status = (int) curl_getinfo($curl, CURLINFO_HTTP_CODE);
  $response = json_decode($result, true);

  curl_close($curl);

  return [
    'error' => $error,
    'status' => $status,
    'response' => $response,
  ];
}

[labbati]

I assume you miss the accept header in the request.

No luck in recreating it.

$ch = curl_init();
curl_setopt_array($ch, [
    CURLOPT_URL => 'http://httpbin_integration/headers',
    CURLOPT_USERPWD => 'clark:kent',
    CURLOPT_HTTPHEADER => ['Accept: application/json'],
    CURLOPT_RETURNTRANSFER => true,
    CURLOPT_FAILONERROR => false,
    CURLOPT_HEADER => false,
]);
$found = json_decode(curl_exec($ch), 1);

Gives

Array
(
    [headers] => Array
        (
            [Accept] => application/json
            [Authorization] => Basic Y2xhcms6a2VudA==
            [Host] => httpbin_integration
            [X-Datadog-Parent-Id] => 296003639066089052
            [X-Datadog-Sampling-Priority] => 1
            [X-Datadog-Trace-Id] => 5730443082975975217
        )

)

I will try to replicate in a real server. How are you @fbaligant serving php app? php-fpm 7.1 + nginx?

[fbaligant]

@labbati This specific platform is on Apache 2.4 + PHP 7.1 FPM using a ProxyPass fcgi:// setup.

[labbati]

Thanks for sharing. I will try to replicate it in docker env. In case I am not able to replicate would you be available to test a custom build specifically build for this purpose which contains some additional debug logs? Of course only if you are able to replicate the issue in a non-production environment.

[fbaligant]

@labbati Customer managed to reproduce in preproduction environment so it is possible to test a debug version of the agent.

[labbati]

Just an heads-up. We created a docker file to try to recreate with no luck yet.

Branch: https://github.com/DataDog/trace-examples/tree/php/labbati/curl-webservice/php

docker-compose up laravel57_php71_apache_fpm

The Host header is correctly propagated

$ curl http://localhost:7071/index.php/curl-webservice

Here is the answer from httpbin: {
    "headers": {
        "Accept": "application\/json",
        "Authorization": "Basic Y2xhcms6a2VudA==",
        "Host": "api.vi.example.com",    <------- manually set
        "X-Datadog-Parent-Id": "579986565124440932",
        "X-Datadog-Sampling-Priority": "1",
        "X-Datadog-Trace-Id": "1527911308917882201"
    }
}

Next step is to create a debug build to verify if this may be possibly related to the fact that in certain conditions, not yet deterministically determined, we have the arguments passed with wrong references.

[labbati]

First of all thank you so much for being open to help us debug this issue. This is really appreciated.

Here is the debug build I was mentioning: packages.tar.gz

Steps:

• install this build (untar and install the .deb/.rpm as you would do with any release)
• set env DD_TRACE_DEBUG=true make sure you set at the right time
• restart the server
• curl http://example.com/your/path
• App should start to populate your error logs with a lot of info related to tracing. Among them I would like to know if messages containing ArrayKVStore appear.

I am of course open to provide help if anything is not clear enough.

[fbaligant]

@labbati I wanted to check with you that you didn't bump the version in this debug package and so it's normal for the trace agent to log version "0.16.1":

2019-03-28 18:00:48 INFO (api.go:341) - [lang:php lang_version:7.1.12-1+ubuntu14.04.1+deb.sury.org+1 interpreter:fpm-fcgi tracer_version:0.16.1] -> traces received: 2, traces dropped: 0, traces filtered: 0, traces amount: 36335 bytes, services received: 0, services amount: 0 bytes, events extracted: 0, events sampled: 0

Asking because I can't see any "ArrayKVStore" into the DD_TRACE_DEBUG output in the error_log tough I can the new span created by the curl_exec call.

[labbati]

That is strange. Extracting the deb file from the archive it gives me the name datadog-php-tracer_0.17.0_amd64.deb and inside I see the relevant file marked as 0.17.0.

Moreover if I install the package above it gives me this in the agent's logs

[ TRACE ] 2019-03-29 11:56:53 INFO (api.go:341) - [lang:php lang_version:7.1.27 interpreter:fpm-fcgi tracer_version:0.17.0] -> traces received: 1, traces dropped: 0, traces filtered: 0, traces amount: 884 bytes, services received: 0, services amount: 0 bytes, events extracted: 0, events sampled: 0

Are you using the deb or another package format? Alternatively, is it possible that more than one tracer is reporting to the same agent?

[fbaligant]

@labbati The reason we see "0.16.1" is because the customer vendored DDTrace in his application and this has priority in the autoloader compared to /opt/datadog-php/dd-trace-sources/src/DDTrace/. So this mystery is solved.

Now on the bug itself, what I found is that "curl_setopt_array" doesn't trigger the hook in DDTrace/Integrations/Curl/CurlIntegration.php:

        dd_trace('curl_setopt_array', function ($ch, $options) use ($globalConfig) {

"curl_setopt" and "curl_exec" function does trigger the hook. As the "curl_setopt_array" hook isn't called, user headers aren't saved to the KV store and the KV store is empty with the Distributed Tracing inject the new headers using curl_setopt.

No idea why curl_setopt_array doesn't trigger the hook yet.

[labbati]

@fbaligant

The reason we see "0.16.1" is because the customer vendored DDTrace in his application

Yep composer gets precedence. Just a small comment here: We observed in the past users that added our dependency to the composer because they thought it was required. It is not and we changed the docs to make sure this was more clear. It is only required if the user wants to perform some manual instrumentation and the open tracing api is not enough.

About the bug this it is surprising actually and I have not an immediate answer to it. While our team members that work on the PHP extension (@pawelchcki and @SammyK) can take a high level look at it, I believe our best option is to try to build an environment as similar as yours.

Ideally, if you have a docker file you can share with us it would be great. Otherwise, knowing the exact OS and version, curl version (the actual deb/rpm package) could be a step forward.

I think that the key here is for us to replicate and debug using gdb or similar.

Thanks for the investigation!

[labbati]

Hi @fbaligant and @tot-ra, not sure if you have seen my previous post. Did you have a chance to provide us with a dockerfile of your env or the exact OS and version, curl version (the actual deb/rpm package)?

Thanks again

[labbati]

Good news, we were able to replicate with curl 7.47.0. https://github.com/DataDog/dd-trace-php/tree/curl/missing-headers/tests/ManualTesting/CurlMissingHttpHeaders

We will work to address it ASAP and post updates to this issue.

[fbaligant]

@labbati thanks for your update on this issue. Looking forward for a fixed build to test.

[labbati]

Sorry this issue was closed by mistake

[pawelchcki]

with 0.19.1 we've released a fix that should address this issue. However feel free to reopen it if you still encounter it.

[labbati]

Hi @fbaligant, did you have a chance to test the new version 0.19.1? Did it correctly work? Thanks!