/[drupal]/contributions/modules/trace/trace.module
ViewVC logotype

Contents of /contributions/modules/trace/trace.module

Parent Directory Parent Directory | Revision Log Revision Log | View Revision Graph Revision Graph


Revision 1.13 - (show annotations) (download) (as text)
Fri Sep 18 15:07:47 2009 UTC (2 months, 1 week ago) by arto
Branch: MAIN
CVS Tags: DRUPAL-6--1-0, HEAD
Changes since 1.12: +11 -4 lines
File MIME type: text/x-php
Fixed a stray PHP notice and limited the nesting depth of data structure output in stack traces.
1 <?php
2 // $Id$
3
4 /**
5 * @file
6 *
7 * Adds tracing facilities for Drupal hook invocations, database queries and
8 * PHP errors.
9 */
10
11 //////////////////////////////////////////////////////////////////////////////
12
13 /**
14 * Call full bootstrap to make use of path checking & file functions early on.
15 * See also: http://api.drupal.org/api/file/includes/path.inc/6
16 */
17 drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
18
19 define('TRACE_PATH', dirname(__FILE__));
20 define('TRACE_FORMAT', "#%s %s [%s]");
21 define('TRACE_ENABLED', variable_get('trace_enabled', FALSE));
22 define('TRACE_FILTER', variable_get('trace_filter', 0));
23 define('TRACE_PAGES', variable_get('trace_pages', "admin*\nfavicon.ico\n"));
24 define('TRACE_OUTPUT', variable_get('trace_output', 'file'));
25 define('TRACE_FILE', variable_get('trace_file', file_directory_path() . '/trace.log'));
26 define('TRACE_ERRORS', count(array_filter(variable_get('trace_errors', array()))) > 0);
27 define('TRACE_WATCHDOG', count(array_filter(variable_get('trace_watchdog', array()))) > 0);
28 define('TRACE_QUERIES', count(array_filter(variable_get('trace_queries', array()))) > 0);
29 define('TRACE_HOOKS', count(array_filter(variable_get('trace_hooks', array()))) > 0);
30 define('TRACE_REQUEST', variable_get('trace_request', TRUE));
31 define('TRACE_DEBUG', variable_get('trace_debug', FALSE));
32 define('TRACE_STACKTRACE', variable_get('trace_stacktrace', FALSE));
33 define('TRACE_MAX_STRING', (integer)variable_get('trace_max_string', 100));
34 define('TRACE_ERRORLINE', variable_get('trace_errorline', FALSE));
35
36 define('TRACE_ACTIVE', TRACE_ENABLED && trace_path_enabled($_GET['q']));
37
38 if (TRACE_ACTIVE) {
39 define('TRACE_TIME', trace_time(FALSE));
40 define('TRACE_ID', substr(uniqid(''), 5));
41 _trace_ob_start();
42 }
43
44 //////////////////////////////////////////////////////////////////////////////
45
46 /**
47 * Implements hook_help(). Provide online user help.
48 */
49 function trace_help($path, $arg) {
50 if (TRACE_ACTIVE && TRACE_HOOKS) {
51 trace_hook('help');
52 }
53
54 switch ($path) {
55 case 'admin/modules#name':
56 return t('trace');
57 case 'admin/modules#description':
58 return t('Adds tracing facilities for Drupal hook invocations, database queries and PHP errors.');
59 }
60 }
61
62 /**
63 * Implements hook_menu(). Define menu items and page callbacks.
64 */
65 function trace_menu() {
66 if (TRACE_ACTIVE && TRACE_HOOKS) {
67 trace_hook('menu');
68 }
69 return array(
70 'admin/settings/trace' => array(
71 'title' => 'Tracing',
72 'description' => 'Enable or disable tracing facilities for Drupal hook invocations, database queries and PHP errors.',
73 'access arguments' => array('administer site configuration'),
74 'page callback' => 'drupal_get_form',
75 'page arguments' => array('trace_settings'),
76 ),
77 'admin/trace' => array(
78 'type' => MENU_CALLBACK,
79 'access arguments' => array('administer site configuration'),
80 'page callback' => 'trace_admin_log',
81 ),
82 );
83 }
84
85 /**
86 * Implements hook_settings(). Declare administrative settings for a module.
87 */
88 function trace_settings() {
89 if (TRACE_ACTIVE && TRACE_HOOKS) {
90 trace_hook('settings');
91 }
92
93 require_once TRACE_PATH . '/trace.admin.inc';
94 return trace_settings_form();
95 }
96
97 /**
98 * Implements hook_boot(). Perform setup tasks, even for cached pages.
99 */
100 function trace_boot() {
101 if (TRACE_ACTIVE) {
102 if (TRACE_DEBUG) {
103 trace('debug', '$_ENV = ' . trace_format_php($_ENV));
104 trace('debug', '$_SERVER = ' . trace_format_php($_SERVER));
105 trace('debug', '$_COOKIE = ' . trace_format_php($_COOKIE));
106 trace('debug', '$_REQUEST = ' . trace_format_php($_REQUEST));
107 if ($_SERVER['REQUEST_METHOD'] == 'GET') {
108 trace('debug', '$_GET = ' . trace_format_php($_GET));
109 }
110 else if ($_SERVER['REQUEST_METHOD'] == 'POST') {
111 trace('debug', '$_POST = ' . trace_format_php($_POST));
112 trace('debug', '$_FILES = ' . trace_format_php($_FILES));
113 }
114 trace('debug', '$_SESSION = ' . trace_format_php($_SESSION));
115 }
116
117 if (TRACE_HOOKS) {
118 trace_hook('boot');
119 }
120 }
121 }
122
123 /**
124 * Implements hook_exit(). Perform cleanup tasks.
125 */
126 function trace_exit($destination = NULL) {
127 if (TRACE_ACTIVE) {
128 if (TRACE_HOOKS) {
129 trace_hook('exit');
130 }
131
132 if (TRACE_DEBUG) {
133 trace('debug', 'drupal_set_message() = ' . trace_format_php(drupal_set_message()));
134 trace('debug', 'drupal_set_header() = ' . trace_format_php(explode("\n", drupal_set_header())));
135 }
136 }
137 }
138
139 //////////////////////////////////////////////////////////////////////////////
140 // TRACE START/EXIT HANDLERS
141
142 /**
143 *
144 */
145 function trace_time($delta = TRUE) {
146 list($usec, $sec) = explode(' ', microtime());
147 $time = ((double)$usec + (double)$sec);
148
149 // NOTE: we can't rely on $_SERVER['REQUEST_TIME'] for the request start
150 // time as it isn't accurate enough (no sub-second precision) and it's not
151 // available prior to PHP 5.1, anyway.
152 return !$delta ? $time : $time - TRACE_TIME;
153 }
154
155 /**
156 * Matches the user's traceability settings against the page path.
157 */
158 function trace_path_enabled($path) {
159 $alias = drupal_get_path_alias($path);
160 return !(TRACE_FILTER xor drupal_match_path($alias, TRACE_PAGES));
161 }
162
163 function _trace_ob_start() {
164 $timestamp = _trace_format_timestamp();
165
166 if (TRACE_ERRORS) {
167 // Extend Drupal's error handler so that we catch warnings and errors:
168 set_error_handler('trace_error_handler');
169 }
170
171 if (TRACE_HOOKS) {
172 // Inject tracing code into all selected Drupal hooks:
173 foreach (trace_hook_list(NULL, TRUE) as $hook) {
174 trace_hook_define('trace', $hook);
175 }
176 }
177
178 if (TRACE_QUERIES) {
179 variable_set('dev_query', TRUE); // FIXME!
180 }
181
182 if (TRACE_REQUEST) {
183 $msg = array($timestamp, $_SERVER['REQUEST_METHOD'], $_SERVER['REQUEST_URI'], $_SERVER['SERVER_PROTOCOL']);
184 trace('request', implode(' ', $msg), 0);
185 }
186
187 ob_start('_trace_ob_handler');
188 }
189
190 function _trace_ob_handler($buffer) {
191 global $queries;
192 $timestamp = _trace_format_timestamp();
193
194 // Ensure we're in the correct working directory, since some web servers
195 // (e.g. Apache) mess this up for exit-time handlers:
196 chdir(dirname($_SERVER['SCRIPT_FILENAME']));
197
198 // This is not ideal, but if no hooks were traced, we have to get the
199 // queries here at the end of the page request. Timing information is
200 // going to be entirely unaccurate, of course.
201 if (TRACE_QUERIES) {
202 trace_queries();
203 }
204
205 // Output some statistics about the page response
206 if (TRACE_DEBUG && count($queries) > 0) {
207 trace('stats', sprintf('Total SQL queries: %d', count($queries)));
208 }
209
210 if (TRACE_REQUEST) {
211 $msg = array($timestamp, _trace_get_http_response());
212 trace('respnse', implode(' ', $msg));
213 }
214
215 return $buffer; // Pass through page contents unmodified
216 }
217
218 //////////////////////////////////////////////////////////////////////////////
219 // Menu callbacks
220
221 function trace_admin_log() {
222 drupal_set_header('Content-Type: text/plain; charset=utf-8');
223 die(implode("\n", array_reverse(array_slice(file(TRACE_FILE), -10))));
224 }
225
226 //////////////////////////////////////////////////////////////////////////////
227 // Trace hooks API
228
229 /**
230 * Implements hook_trace().
231 */
232 function trace_trace($type, $msg, $time = NULL) {
233 if (TRACE_OUTPUT) {
234 // Delegate to the actual selected output driver:
235 $driver = 'trace_' . TRACE_OUTPUT . '_trace';
236 if (!function_exists($driver)) {
237 require_once TRACE_PATH . '/drivers/' . TRACE_OUTPUT . '.inc';
238 }
239 return $driver($type, $msg, $time);
240 }
241 }
242
243 //////////////////////////////////////////////////////////////////////////////
244 // Trace error API
245
246 /**
247 * Custom error handler with tracing support.
248 */
249 function trace_error_handler($errno, $message, $filename, $line) {
250 static $types = array(1 => 'E_ERROR', 2 => 'E_WARNING', 4 => 'E_PARSE', 8 => 'E_NOTICE', 16 => 'E_CORE_ERROR', 32 => 'E_CORE_WARNING', 64 => 'E_COMPILE_ERROR', 128 => 'E_COMPILE_WARNING', 256 => 'E_USER_ERROR', 512 => 'E_USER_WARNING', 1024 => 'E_USER_NOTICE', 2048 => 'E_STRICT', 4096 => 'E_RECOVERABLE_ERROR');
251 static $options = NULL;
252 if (!$options) {
253 $options = array_filter(variable_get('trace_errors', array()), 'is_string');
254 }
255
256 $output = array(sprintf("%s: %s in `%s':%s", $types[$errno], $message, _trace_format_filename($filename), $line));
257 if (TRACE_ERRORLINE && ($code = _trace_get_line_from_file($filename, $line))) {
258 $output[] = trim($code);
259 }
260 if (TRACE_STACKTRACE) {
261 $stacktrace = array_map('_trace_format_stack_frame', array_slice(debug_backtrace(), 1));
262 $output = array_merge($output, $stacktrace);
263 }
264
265 $type = 'error';
266 $type = ($errno == E_WARNING || $errno == E_USER_WARNING ? 'warning' : $type);
267 $type = ($errno == E_NOTICE || $errno == E_USER_NOTICE || $errno == 2048 ? 'notice' : $type); // PHP4 compatible
268 if (!empty($options[$type])) {
269 trace($type, $output);
270 }
271
272 // Delegate to the standard Drupal error handler:
273 return drupal_error_handler($errno, $message, $filename, $line, NULL);
274 }
275
276 //////////////////////////////////////////////////////////////////////////////
277 // Trace procedural API
278
279 /**
280 * Invokes hook_trace() with the specified arguments.
281 *
282 * If passed just argument, will use it for the trace message and default to
283 * 'debug' for the trace message type.
284 */
285 function trace($type, $msg = NULL, $time = NULL) {
286 if (func_num_args() == 1) {
287 $type = 'debug';
288 $msg = func_get_arg(0);
289 }
290 call_user_func_array('module_invoke_all', array('trace', $type, $msg, $time));
291 }
292
293 function trace_dump($value) {
294 trace(trace_format_php($value));
295 }
296
297 /**
298 * Traces the entire function call chain leading up to this point,
299 * outputting a log entry of the DEBUG type.
300 */
301 function trace_backtrace($depth = -1) {
302 // FIXME: add support for $depth.
303 trace('debug', array_map('_trace_format_stack_frame', array_slice(debug_backtrace(), 1)));
304 }
305
306 function trace_query($query, $caller = NULL, $time = NULL, $duration = NULL) {
307 // TODO: only trace queries matching configuration settings.
308 trace('query', sprintf('d=%.6fs %s: %s', $duration, $caller, $query), ($time ? $time : trace_time()));
309 }
310
311 function trace_queries() {
312 global $queries;
313 static $last_query = 0;
314 static $options = NULL;
315 if (!$options) {
316 $options = variable_get('trace_queries', array());
317 }
318
319 if (count($queries) > $last_query) {
320 $time = trace_time();
321 $new_queries = array();
322 foreach (array_reverse(array_slice($queries, $last_query)) as $query) {
323 list($query, $diff) = $query;
324 $query = preg_replace("/\/\*(.*)\*\/\s/", '', $query); // Drupal 6.x adds user & function info in a comment at the front
325 $query = array_reverse(explode("\n", $query));
326
327 $type = explode(' ', reset($query));
328 $type = strtolower(reset($type));
329 if (array_key_exists($type, $options) && empty($options[$type]))
330 continue; // skip any known query types that are not enabled
331 if (!array_key_exists($type, $options) && empty($options['misc']))
332 continue; // skip query unless the 'Other queries' option is enabled
333
334 $new_queries[] = array_merge($query, array($time -= $diff, $diff));
335 }
336 foreach (array_reverse($new_queries) as $query) {
337 call_user_func_array('trace_query', $query);
338 }
339
340 $last_query = count($queries);
341 }
342 }
343
344 function trace_hook($hook) {
345 if (!trace_hook_enabled($hook)) {
346 return;
347 }
348 if (TRACE_QUERIES) {
349 trace_queries();
350 }
351 $stacktrace = !TRACE_STACKTRACE ? NULL : array_map('_trace_format_stack_frame', array_slice(debug_backtrace(), 1));
352 trace('hook', _trace_format_hook_entry($hook, $stacktrace));
353 }
354
355 function trace_hook_implementors($hook) {
356 static $modules = array();
357 if (!isset($modules[$hook])) {
358 $modules[$hook] = module_implements($hook);
359
360 // Remove this module from the list:
361 if (($key = array_search('trace', $modules[$hook])) !== FALSE)
362 unset($modules[$hook][$key]);
363 }
364 return empty($modules[$hook]) ? array() : $modules[$hook];
365 }
366
367 function trace_hook_enabled($hook) {
368 static $enabled_hooks = NULL;
369 if (!$enabled_hooks) {
370 $enabled_hooks = array_filter(variable_get('trace_hooks', array()), 'is_string');
371 }
372 return isset($enabled_hooks[$hook]);
373 }
374
375 function trace_hook_defined($module, $hook) {
376 return function_exists($module . '_' . $hook);
377 }
378
379 /**
380 * Defines a Drupal hook function containing tracing code.
381 */
382 function trace_hook_define($module, $hook) {
383 static $skipped_hooks = array('enable', 'disable', 'install', 'uninstall'); // prevent conflicts
384 if (!trace_hook_defined($module, $hook)) {
385 if ($module != 'trace' || !in_array($hook, $skipped_hooks)) {
386 eval("function {$module}_$hook() { trace_hook('$hook'); }");
387 return TRUE;
388 }
389 }
390 return FALSE;
391 }
392
393 function trace_hook_list($module = NULL, $only_enabled = FALSE) {
394 $hooks = parse_ini_file(TRACE_PATH . '/hooks.ini', !empty($module));
395 $hooks = array_merge(array_keys(!empty($module) ? $hooks[$module] : $hooks));
396 return !$only_enabled ? $hooks : array_filter($hooks, 'trace_hook_enabled');
397 }
398
399 function trace_hook_data() {
400 return parse_ini_file(TRACE_PATH . '/hooks.ini', TRUE);
401 }
402
403 //////////////////////////////////////////////////////////////////////////////
404 // Miscellaneous helpers
405
406 function _trace_get_http_response() {
407 $status = '200 OK';
408 $headers = explode("\n", drupal_set_header());
409 foreach ($headers as $header) {
410 if (preg_match('!^HTTP/!', $header)) {
411 list($prefix, $status) = explode(' ', $header, 2);
412 }
413 }
414 return $status;
415 }
416
417 function _trace_get_line_from_file($filename, $line) {
418 $result = NULL;
419 if (file_exists($filename) && ($fp = fopen($filename, 'r'))) {
420 $counter = 0;
421 while (!feof($fp) && ($buffer = fgets($fp))) {
422 if (++$counter == $line) {
423 $result = $buffer;
424 break;
425 }
426 }
427 fclose($fp);
428 }
429 return $result;
430 }
431
432 //////////////////////////////////////////////////////////////////////////////
433 // Trace format helpers
434
435 function _trace_format_timedelta($t = NULL) {
436 $t = !is_null($t) ? $t : trace_time(TRUE);
437 return $t === 0 ? sprintf('T=%.6f', 0.0) : sprintf('T%s%.6f', ($t < 0 ? '-' : '+'), abs($t));
438 }
439
440 function _trace_format_timestamp() {
441 list($usec, $time) = explode(' ', microtime());
442 if (function_exists('date_default_timezone_set')) {
443 date_default_timezone_set('UTC'); // // avoid E_STRICT message in PHP 5.1+
444 }
445 if (($timezone = variable_get('date_default_timezone', 0))) {
446 $time += $timezone; // Adjust to Drupal default timezone
447 }
448 return sprintf('%s.%s', strftime('%Y-%m-%d %H:%M:%S', (int)$time), substr($usec, 2, 6));
449 }
450
451 function _trace_format_hook_entry($hook, $stacktrace = NULL) {
452 $modules = implode(', ', trace_hook_implementors($hook));
453 $output = array(sprintf('hook_%s: %s', $hook, $modules));
454 if (!empty($stacktrace)) {
455 $output = array_merge($output, $stacktrace);
456 }
457 return $output;
458 }
459
460 function _trace_format_stack_frame($frame) {
461 $function_call = _trace_format_function_call($frame['function'], $frame['args']);
462 return (empty($frame['file']) || empty($frame['line']) ?
463 $function_call :
464 sprintf("%s in `%s':%s", $function_call, _trace_format_filename($frame['file']), $frame['line']));
465 }
466
467 function _trace_format_filename($filename) {
468 if (($cwd = getcwd()) && strpos($filename, $cwd) === 0) {
469 return substr($filename, strlen($cwd) + 1);
470 }
471 return $filename;
472 }
473
474 function _trace_format_function_call($function, $args) {
475 // NOTE: Can't use array_map() here due to weird warning output it causes on PHP5
476 //$args = implode(', ', array_map('trace_format_php', $args));
477 $output = array();
478 if (is_array($args)) {
479 foreach ($args as $arg) {
480 $output[] = trace_format_php($arg);
481 }
482 }
483 return $function . '(' . implode(', ', $output) . ')';
484 }
485
486 function _trace_format_watchdog_entry($severity, $msg) {
487 // TODO
488 }
489
490 //////////////////////////////////////////////////////////////////////////////
491 // Trace helpers
492
493 function trace_format_php($value, $depth = 0) {
494 switch (gettype($value)) {
495 case 'NULL':
496 return 'NULL';
497 case 'boolean':
498 return $value ? 'TRUE' : 'FALSE';
499 case 'integer':
500 case 'double':
501 return (string)$value;
502 case 'string':
503 if (TRACE_MAX_STRING > 0 && strlen($value) > TRACE_MAX_STRING) {
504 $suffix = TRUE;
505 $value = substr($value, 0, TRACE_MAX_STRING);
506 }
507 $value = str_replace(array("'", "\n", "\r", "\t"), array("\\'", '\n', '\r', '\t'), $value);
508 return "'$value'" . (!empty($suffix) ? '...' : '');
509 case 'object':
510 $class = get_class($value);
511 $value = (array)$value;
512 // fall through
513 case 'array':
514 // Limit recursion to something sane to prevent massive output (as
515 // well as XDebug bailing out) with stack traces containing deep data
516 // structures:
517 if ($depth > 1) {
518 $array = array('...');
519 }
520 else if (array_keys($value) === range(0, sizeof($value) - 1)) {
521 $array = array_map('trace_format_php', array_values($value));
522 }
523 else {
524 $array = array();
525 foreach ($value as $k => $v) {
526 $array[] = trace_format_php($k, $depth + 1) . ' => ' . trace_format_php($v, $depth + 1);
527 }
528 }
529 $array = implode(', ', $array);
530 return (isset($class) ? "($class)" : '') . 'array(' . $array . ')';
531 case 'resource':
532 return 'resource(' . get_resource_type($value) . ')';
533 default:
534 return '<unknown>';
535 }
536 }

  ViewVC Help
Powered by ViewVC 1.1.2