Skip to content

Profile is not present for current request #737

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
edxeth opened this issue Mar 20, 2025 · 2 comments
Open

Profile is not present for current request #737

edxeth opened this issue Mar 20, 2025 · 2 comments

Comments

@edxeth
Copy link

edxeth commented Mar 20, 2025 •
edited
Loading

Hi!
I cannot get Clockwork to parse the profiles, as per title I get:

Profile is not present for current request.
Profiling requires the Xdebug php extension.

The Docker image I used is dunglas/frankenphp:1.4.4-php8.4.5-alpine
php.ini

date.timezone = UTC
error_reporting = E_ALL
display_errors = On
log_errors = On
error_log = /var/log/php/error.log
disable_functions = exec,passthru,shell_exec,system,proc_open,popen
default_mimetype = ""

# xdebug
xdebug.mode = debug,profile
xdebug.start_with_request = trigger
xdebug.profiler_output_name = cachegrind.out.%u.%r
xdebug.use_compression = 1
xdebug.cli_color = 2
xdebug.client_host = host.docker.internal
xdebug.client_port = 9003
xdebug.idekey = VSCODE
xdebug.log_level = 1
xdebug.log = /var/log/php/xdebug.log
xdebug.output_dir = /tmp/xdebug-profiles
  • resorting to xdebug.mode profile and xdebug.start_with_request yes does not help either, FYI!

Let's browse http://localhost/clockwork and run curl -v "http://localhost/api/users/123?XDEBUG_PROFILE" to see what gets logged:
./logs/php/frankenphp/error.log:

[20-Mar-2025 16:24:22 UTC] Xdebug Trigger Check: Array
(
    [URI] => /__clockwork/1742487654-2437-1172311431/next
    [GET] => not set
    [COOKIE] => 1
    [PROFILER] => debug,profile
)

[20-Mar-2025 16:24:27 UTC] Xdebug Trigger Check: Array
(
    [URI] => /__clockwork/1742487654-2437-1172311431/next
    [GET] => not set
    [COOKIE] => 1
    [PROFILER] => debug,profile
)

[20-Mar-2025 16:24:27 UTC] Xdebug Trigger Check: Array
(
    [URI] => /api/users/123?XDEBUG_PROFILE
    [GET] => 
    [COOKIE] => not set
    [PROFILER] => debug,profile
)

[20-Mar-2025 16:24:32 UTC] Xdebug Trigger Check: Array
(
    [URI] => /__clockwork/1742487654-2437-1172311431/next
    [GET] => not set
    [COOKIE] => 1
    [PROFILER] => debug,profile
)

[20-Mar-2025 16:24:32 UTC] Xdebug Trigger Check: Array
(
    [URI] => /__clockwork/1742487870-2626-1801051706/next
    [GET] => not set
    [COOKIE] => 1
    [PROFILER] => debug,profile
)

[20-Mar-2025 16:24:33 UTC] Xdebug Trigger Check: Array
(
    [URI] => /__clockwork/1742487870-2626-1801051706/next
    [GET] => not set
    [COOKIE] => 1
    [PROFILER] => debug,profile
)

Logger:

use Clockwork\Support\Vanilla\Clockwork;

$clockwork = Clockwork::init([
    'storage_files_path' => '/tmp/clockwork',
    'register_helpers' => true,
    'web' => [
        'enable' => true,
        'path' => __DIR__ . '/vendor/clockwork',
        'uri' => '/vendor/clockwork'
    ]
]);

error_log('Xdebug Trigger Check: ' . print_r([
    'URI' => $_SERVER['REQUEST_URI'],
    'GET' => isset($_GET['XDEBUG_PROFILE']) ? $_GET['XDEBUG_PROFILE'] : 'not set',
    'COOKIE' => isset($_COOKIE['XDEBUG_PROFILE']) ? $_COOKIE['XDEBUG_PROFILE'] : 'not set',
    'PROFILER' => ini_get('xdebug.mode'),
], true));

The curl request:

❯ curl -v "http://localhost/api/users/123?XDEBUG_PROFILE"
* Host localhost:80 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
*   Trying [::1]:80...
* Connected to localhost (::1) port 80
* using HTTP/1.x
> GET /api/users/123?XDEBUG_PROFILE HTTP/1.1
> Host: localhost
> User-Agent: curl/8.10.1
> Accept: */*
>
* Request completely sent off
< HTTP/1.1 200 OK
< Content-Type: application/json
< Server: Caddy
< Server-Timing: app; dur=9.0548992156982; desc="Application"
< Set-Cookie: x-clockwork=%7B%22requestId%22%3A%221742487867-7726-1940135706%22%2C%22version%22%3A%225.3.4%22%2C%22path%22%3A%22%5C%2F__clockwork%5C%2F%22%2C%22webPath%22%3Atrue%2C%22token%22%3A%22f275bb6c%22%2C%22metrics%22%3Atrue%2C%22toolbar%22%3Atrue%7D; expires=Thu, 20 Mar 2025 16:25:27 GMT; Max-Age=60
< X-Clockwork-Id: 1742487867-7726-1940135706
< X-Clockwork-Version: 5.3.4
< X-Xdebug-Profile-Filename: /tmp/xdebug-profiles/cachegrind.out.1742487867.792519.09909d.gz
< Date: Thu, 20 Mar 2025 16:24:27 GMT
< Content-Length: 204
<
{
    "data": {
        "type": null,
        "id": "123",
        "attributes": {
            "name": "John Doe",
            "email": "[email protected]",
            "balance": 1500.75
        }
    }
}* Connection #0 to host localhost left intact

xdebug info:

❯ docker exec -it frankenphp sh
~ $ php -r 'xdebug_info();'

__   __   _      _                 
\ \ / /  | |    | |                
 \ V / __| | ___| |__  _   _  __ _ 
  > < / _` |/ _ \ '_ \| | | |/ _` |
 / . \ (_| |  __/ |_) | |_| | (_| |
/_/ \_\__,_|\___|_.__/ \__,_|\__, |
                              __/ |
                             |___/ 

Version => 3.4.1
Support Xdebug on Patreon, GitHub, or as a business: https://xdebug.org/support

             Enabled Features (through 'xdebug.mode' setting)             
Feature => Enabled/Disabled
Development Helpers => ✘ disabled
Coverage => ✘ disabled
GC Stats => ✘ disabled
Profiler => ✔ enabled
Step Debugger => ✔ enabled
Tracing => ✘ disabled

                            Optional Features                            
Compressed File Support => yes (gzip)
Clock Source => clock_gettime
TSC Clock Source => available
'xdebug://gateway' pseudo-host support => yes
'xdebug://nameserver' pseudo-host support => no
Systemd Private Temp Directory => not enabled

                              Diagnostic Log                              
No messages

                              Step Debugging                              
Debugger is not active

                                 Profiler                                 
Profiler is not active

                                   PHP                                   
                           Build Configuration                           
Version (Run Time) => 8.4.5
Version (Compile Time) => 8.4.5
Debug Build => no
Thread Safety => enabled
Thread API => POSIX Threads
                                 Settings                                 
Configuration File (php.ini) Path => /usr/local/etc/php
Loaded Configuration File => /usr/local/etc/php/php.ini
Scan this dir for additional .ini files => /usr/local/etc/php/conf.d
Additional .ini files parsed => /usr/local/etc/php/conf.d/docker-php-ext-bcmath.ini,
/usr/local/etc/php/conf.d/docker-php-ext-mongodb.ini,
/usr/local/etc/php/conf.d/docker-php-ext-opcache.ini,
/usr/local/etc/php/conf.d/docker-php-ext-redis.ini,
/usr/local/etc/php/conf.d/docker-php-ext-sodium.ini,
/usr/local/etc/php/conf.d/docker-php-ext-xdebug.ini,
/usr/local/etc/php/conf.d/docker-php-ext-zip.ini


Directive => Local Value => Master Value
xdebug.mode => debug,profile => debug,profile
xdebug.start_with_request => trigger => trigger
xdebug.start_upon_error => default => default
xdebug.output_dir => /tmp/xdebug-profiles => /tmp/xdebug-profiles
xdebug.use_compression => 1 => 1
xdebug.trigger_value => no value => no value
xdebug.file_link_format => no value => no value
xdebug.filename_format => no value => no value
xdebug.control_socket => time: 25ms => time: 25ms
xdebug.log => /var/log/php/xdebug.log => /var/log/php/xdebug.log
xdebug.log_level => 1 => 1
xdebug.var_display_max_children => 128 => 128
xdebug.var_display_max_data => 512 => 512
xdebug.var_display_max_depth => 3 => 3
xdebug.max_nesting_level => 512 => 512
xdebug.cli_color => 2 => 2
xdebug.force_display_errors => Off => Off
xdebug.force_error_reporting => 0 => 0
xdebug.halt_level => 0 => 0
xdebug.max_stack_frames => -1 => -1
xdebug.show_error_trace => Off => Off
xdebug.show_exception_trace => Off => Off
xdebug.show_local_vars => Off => Off
xdebug.dump.COOKIE => no value => no value
xdebug.dump.ENV => no value => no value
xdebug.dump.FILES => no value => no value
xdebug.dump.GET => no value => no value
xdebug.dump.POST => no value => no value
xdebug.dump.REQUEST => no value => no value
xdebug.dump.SERVER => no value => no value
xdebug.dump.SESSION => no value => no value
xdebug.dump_globals => On => On
xdebug.dump_once => On => On
xdebug.dump_undefined => Off => Off
xdebug.profiler_output_name => cachegrind.out.%u.%r => cachegrind.out.%u.%r
xdebug.profiler_append => Off => Off
xdebug.cloud_id => no value => no value
xdebug.client_host => host.docker.internal => host.docker.internal
xdebug.client_port => 9003 => 9003
xdebug.discover_client_host => Off => Off
xdebug.client_discovery_header => HTTP_X_FORWARDED_FOR,REMOTE_ADDR => HTTP_X_FORWARDED_FOR,REMOTE_ADDR
xdebug.idekey => VSCODE => VSCODE
xdebug.connect_timeout_ms => 200 => 200
xdebug.scream => Off => Off
xdebug.gc_stats_output_name => gcstats.%p => gcstats.%p
xdebug.trace_output_name => trace.%c => trace.%c
xdebug.trace_format => 0 => 0
xdebug.trace_options => 0 => 0
xdebug.collect_assignments => Off => Off
xdebug.collect_params => On => On
xdebug.collect_return => Off => Off

Also why is xdebug spamming the /tmp/xdebug-profiles folder with so many generated GZ files? I understand it's because of the polling conducted by Clockwork but is there any way to prevent this kind of behavior? That seems to be garbage profiles to me.
@edxeth
Copy link
Author

edxeth commented Mar 20, 2025

Image
Image

@edxeth
Copy link
Author

edxeth commented Mar 30, 2025 •
edited
Loading

I think there likely is a subtle bug or incompatibility within the Clockwork library specifically when interacting with the FrankenPHP SAPI's lifecycle or filesystem handling during its requestProcessed phase.

Let me demonstrate this through the following code placed right before declaring $clockwork->requestProcessed():

try {
    $profileFile = xdebug_get_profiler_filename();
    if ($profileFile) {
        $fileExists = file_exists($profileFile);
        $clockwork->log()->info("Xdebug profile check: File='{$profileFile}', Exists=" . ($fileExists ? 'true' : 'false'));
    } else {
        $clockwork->log()->warning("Xdebug profile check: xdebug_get_profiler_filename() returned empty.");
    }
} catch (\Throwable $diagError) {
    error_log("Error during Xdebug profile diagnostic check: " . $diagError->getMessage());
    if ($clockwork) {
        $clockwork->log()->error("Error during Xdebug profile diagnostic check: " . $diagError->getMessage());
    }
}

It prints:

Xdebug profile check: File='/tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz', Exists=true

Which matches the response headers in browser devtools:

X-Xdebug-Profile-Filename: /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz

It's needless to say that the file exists in both container and host filesystem:

❯ ls -la /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
-rw-r--r-- 1 edxeth edxeth 37086 Mar 30 23:16 /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
❯ docker exec -it frankenphp ls -la /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
-rw-r--r--    1 dummy dummy     37086 Mar 30 21:16 /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz

Unfortunately the corresponding Clockwork JSON file of the same GET request has an empty xdebug array:

{
  "id": "1743373526-6852-1831031367",
  "version": 1,
  "type": "request",
  "time": 1743373526.640225,
  "method": "GET",
  "url": "http://localhost/",
  "uri": "/",
  "headers": {
    "Accept": [
      "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
    ],
    "Accept-Encoding": [
      "gzip, deflate, br, zstd"
    ],
    "Accept-Language": [
      "en-US,en;q=0.5"
    ],
    "Connection": [
      "keep-alive"
    ],
    "Cookie": [
      "categories=general; language=auto; locale=en; autocomplete=duckduckgo; favicon_resolver=; image_proxy=1; method=POST; safesearch=0; theme=simple; results_on_new_tab=1; doi_resolver=oadoi.org; simple_style=dark; center_alignment=0; advanced_search=0; query_in_title=0; infinite_scroll=1; search_on_category_select=1; hotkeys=default; url_formatting=pretty; disabled_engines=; enabled_engines=; disabled_plugins=; enabled_plugins=; tokens=; XDEBUG_PROFILE=1"
    ],
    "Dnt": [
      "1"
    ],
    "Host": [
      "localhost"
    ],
    "Priority": [
      "u=0, i"
    ],
    "Referer": [
      "http://localhost/"
    ],
    "Sec-Fetch-Dest": [
      "document"
    ],
    "Sec-Fetch-Mode": [
      "navigate"
    ],
    "Sec-Fetch-Site": [
      "same-origin"
    ],
    "Sec-Fetch-User": [
      "?1"
    ],
    "Sec-Gpc": [
      "1"
    ],
    "Upgrade-Insecure-Requests": [
      "1"
    ],
    "User-Agent": [
      "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:136.0) Gecko/20100101 Firefox/136.0"
    ],
    "X-Original-Host": [
      "localhost"
    ]
  },
  "controller": null,
  "getData": [],
  "postData": [],
  "requestData": "",
  "sessionData": [],
  "authenticatedUser": null,
  "cookies": {
    "categories": "general",
    "language": "auto",
    "locale": "en",
    "autocomplete": "duckduckgo",
    "favicon_resolver": "",
    "image_proxy": "1",
    "method": "POST",
    "safesearch": "0",
    "theme": "simple",
    "results_on_new_tab": "1",
    "doi_resolver": "oadoi.org",
    "simple_style": "dark",
    "center_alignment": "0",
    "advanced_search": "0",
    "query_in_title": "0",
    "infinite_scroll": "1",
    "search_on_category_select": "1",
    "hotkeys": "default",
    "url_formatting": "pretty",
    "disabled_engines": "",
    "enabled_engines": "",
    "disabled_plugins": "",
    "enabled_plugins": "",
    "tokens": "",
    "XDEBUG_PROFILE": "1"
  },
  "responseTime": 1743373526.723236,
  "responseStatus": 200,
  "responseDuration": 83.01115036010742,
  "memoryUsage": 2097152,
  "middleware": [],
  "databaseQueries": [],
  "databaseQueriesCount": 0,
  "databaseSlowQueries": 0,
  "databaseSelects": 0,
  "databaseInserts": 0,
  "databaseUpdates": 0,
  "databaseDeletes": 0,
  "databaseOthers": 0,
  "databaseDuration": 0,
  "cacheQueries": [],
  "cacheReads": 0,
  "cacheHits": 0,
  "cacheWrites": 0,
  "cacheDeletes": 0,
  "cacheTime": 0,
  "modelsActions": [],
  "modelsRetrieved": [],
  "modelsCreated": [],
  "modelsUpdated": [],
  "modelsDeleted": [],
  "redisCommands": [],
  "queueJobs": [],
  "timelineData": [],
  "log": [],
  "events": [],
  "routes": [],
  "notifications": [],
  "emailsData": [],
  "viewsData": [],
  "userData": [],
  "httpRequests": [],
  "subrequests": [],
  "xdebug": [],
  "commandName": null,
  "commandArguments": [],
  "commandArgumentsDefaults": [],
  "commandOptions": [],
  "commandOptionsDefaults": [],
  "commandExitCode": null,
  "commandOutput": null,
  "jobName": null,
  "jobDescription": null,
  "jobStatus": null,
  "jobPayload": [],
  "jobQueue": null,
  "jobConnection": null,
  "jobOptions": [],
  "testName": null,
  "testStatus": null,
  "testStatusMessage": null,
  "testAsserts": [],
  "clientMetrics": [],
  "webVitals": [],
  "parent": null,
  "updateToken": "80099cdd"
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@edxeth