3

I expect my server to make one Xdebug dump per request using the php.ini

xdebug.auto_trace=1
xdebug.collect_params=4
xdebug.trace_format=1
xdebug.collect_return=1
xdebug.collect_assignments=1
xdebug.trace_options=0
xdebug.trace_output_dir=/tmp/
xdebug.trace_output_name=xdebug.%R.%U
xdebug.var_display_max_data=16000

I also dump the unique id generated by Apache into a log file which shows:

"GET / HTTP/1.1" "XIZB4KSTHJac6j8l3z6SOwAAAAA"

So far so good - single log entry should mean a single log file. However, my Xdebug dump folder now has more than a single xdebug dump:

xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.0943bc.xt  xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.0e4362.xt
xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.0c6269.xt  xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.xt
xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.0363ec.xt  xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.0cb868.xt

Of which the one matching xdebug._.XIZB4KSTHJac6j8l3z6SOwAAAAA.xt seems to be the legit one based on the content. The other xdebugs are way smaller and do not seem to contain the core calls needed to process the request. However, they do seem related as they share the same id.

What are those extra xdebugs and how can I merge them into the proper xdebug (in case they are actually related to the same request)?

Posting the whole trace files would be a bit much and I generate trace files on code I did not write myself and can consequently not tell you any implementation specifics. However, I dumped below one of the short 'weird' trace files.

Version: 2.6.0
File format: 4
TRACE START [2019-01-08 19:53:33]
1       1119    0       0.056006        797816  MyBB->__destruct        1               /opt/bitnami/apps/mybb/htdocs/inc/class_core.php        0       0
2       1120    0       0.056014        797816  function_exists 0               /opt/bitnami/apps/mybb/htdocs/inc/class_core.php        590     1       'run_shutdown'
2       1120    1       0.056021        797816
2       1120    R                       TRUE
2       1121    0       0.056026        797816  run_shutdown    1               /opt/bitnami/apps/mybb/htdocs/inc/class_core.php        592     0
2       1121    1       0.056032        797816
1       1119    1       0.056035        797816
1       1119    R                       NULL
                        0.056350        38208
TRACE END   [2019-01-08 19:53:33]
Sim
  • 4,199
  • 4
  • 39
  • 77
  • 1
    Your trace files look a lot as if they where created with the lowercase "%r" option which can be used for the config param "xdebug.trace_output_name" and adds a random "number" to the result files (https://xdebug.org/docs/execution_trace). Can you ensure they are from exactly the same call/request, maybe by file creation date? – NiMeDia Mar 18 '19 at 09:31
  • @NicoM yes I can - exact same timestamp with `ls -la` and I am NOT using "%r" anywhere in the configuration and the files are delete before I start collecting them, thus the folder is empty before those weird 'extra' files appear. – Sim Mar 18 '19 at 18:35
  • Sounds weird, are you using some kind of threading or shell_exec calls within your code? Maybe xdebug splits the sub-traces in this way. But that's just a guess, cannot find anything in the docs about it. Could you provide some data of the trace files? – NiMeDia Mar 19 '19 at 05:50
  • @NicoM I added one of the 'weird' trace files. – Sim Mar 20 '19 at 16:45
  • Maybe from some includes or other piece of code with the auto_trace. xdebug.auto_trace Type: boolean, Default value: 0 When this setting is set to on, the tracing of function calls will be enabled just before the script is run. This makes it possible to trace code in the auto_prepend_file. – Tuckbros Mar 20 '19 at 21:57
  • Or just not yours, as the xdebug conf seems to be in php.ini and so global to all php running on the server – Tuckbros Mar 20 '19 at 21:58

1 Answers1

1

From your sample trace and some researches around the topic I MIGHT found an answer to the behaviour you described:

As in https://stackoverflow.com/a/17995870/2833639 stated, shutdown functions run out of the "normal" request stack and debug_backtrace() from registered shutdown function in PHP tells us basically, that you cannot trace within a shutdown function.

Your sample trace tells, that the destructor method of an Object of the class "MyBB" was called.

My ASSUMTION here is that object destructors, like shutdown functions, are handled out of the "normal" stack so Xdebug creates different trace files for each seperate trace of the request (normal trace + x shutdown/destructor calls). Of course I found nothing in the docs about it, but due to the nature of object destruction this seems pretty plausible. Most likely these seperate traces happen after the response of the HTTP-request has taken place, but this depends on the specific implementation.

(I know that answers shouldn't be based on guesses or thougts but I felt that it could be usefull here, so feel free to prove me right or wrong on this point)

NiMeDia
  • 995
  • 1
  • 15
  • 27
  • would you have an idea on how to test this assumption? – Sim Mar 22 '19 at 09:08
  • @Sim You could write a custom php script which instantiates an object of a simple class which has destructor method. If the theory is correct, Xdebug would create 2 files instead of one. – NiMeDia Mar 22 '19 at 09:33