Double loggin

[lunetics]

Somehow doing 2 requests results in 4 requests logged in the profiler / datacollector

[thewilkybarkid]

Is one of those two original requests redirecting? I've just tried it myself and that causes 3 requests to be logged (original request with a 302 response, second request with a 200 response, then a faux original request with the second's response).

I've also encountered problems with the stopwatch.

[lunetics]

Afaik the requests are 200. also send() is only called twice ( but each request duplicate) req1 req2 req1 req2

[thewilkybarkid]

Hmm, would you mind posting what appears in the profiler? (Obviously cutting out any sensitive info.)

[StuBez]

I'm experiencing the same issue.

It seems to happen if the response from the web service doesn't specify that the content should be cached in the cache-control header.

Only one request is actually made but two requests appear in the profiler.

Not enabling the filesystem cache stops the additional request appearing in the profiler.

The requests appear identical, except for the If-Modified-Since header.

The first request was

crampon.internal.admin.cam.ac.uk Guzzle/3.0.7 curl/7.19.7 PHP/5.4.10 - [2013-02-22T15:26:52+00:00] "GET /app_dev.php/api/users/rh1 HTTP/1.1" 200
Request:

GET /app_dev.php/api/users/rh1 HTTP/1.1
Host: janus.dev.ice.internal.admin.cam.ac.uk
User-Agent: Guzzle/3.0.7 curl/7.19.7 PHP/5.4.10
If-Modified-Since: Fri, 22 Feb 2013 14:31:43 GMT

Response:

HTTP/1.1 200 OK
Date: Fri, 22 Feb 2013 15:26:52 GMT
Server: Apache
X-Powered-By: PHP/5.4.10
cache-control: no-cache
x-debug-token: 51278e3cd7893
Vary: Accept-Encoding
Content-Type: application/json
X-Guzzle-Cache: key=GZd4c5df27d2b1a2e3750644d7e64e0ede, ttl=3600

{"id":42,"username":"rh1","enabled":true,"title":"Mr","firstNames":"Roderick","lastNames":"Hill","attributes":[{"fieldName":"xxx","value":"xxx@xxx","created":"2013-02-22T13:47:19+0000"}]}

The second was

crampon.internal.admin.cam.ac.uk Guzzle/3.0.7 curl/7.19.7 PHP/5.4.10 - [2013-02-22T15:26:52+00:00] "GET /app_dev.php/api/users/rh1 HTTP/1.1" 200
Request:

GET /app_dev.php/api/users/rh1 HTTP/1.1
Host: janus.dev.ice.internal.admin.cam.ac.uk
User-Agent: Guzzle/3.0.7 curl/7.19.7 PHP/5.4.10

Response:

HTTP/1.1 200 OK
Date: Fri, 22 Feb 2013 15:26:52 GMT
Server: Apache
X-Powered-By: PHP/5.4.10
cache-control: no-cache
x-debug-token: 51278e3cd7893
Vary: Accept-Encoding
Content-Type: application/json
X-Guzzle-Cache: key=GZd4c5df27d2b1a2e3750644d7e64e0ede, ttl=3600

{"id":42,"username":"rh1","enabled":true,"title":"Mr","firstNames":"Roderick","lastNames":"Hill","attributes":[{"fieldName":"xxx","value":"xxx@xxx","created":"2013-02-22T13:47:19+0000"}]}

[thewilkybarkid]

I think what's happening here is that the no-cache directive is causing a revalidation sub-request to be made (see Guzzle\Plugin\Cache\DefaultRevalidation::revalidate()). The first one you're seeing is the sub-request (the request that was actually made), the second is your request which has been given the sub-request's response.

This is close to the same problem that I've been having with redirects.

In this case the profiler should only show one request, it was not actually a successful revalidation (ie a 304 Not Modified). In case of a successful revalidation it should show one request, but include the validation request/response details somehow. And with redirects show one request, but include the hop details.

[thewilkybarkid]

It looks like changes in Guzzle has resolved this. Presumably the event firing logic has been modified at some point; I'm going to close the issue as I don't think I would be able to fix it for anyone still using earlier versions of Guzzle.

If you are still seeing this behaviour, however, please do reopen.