Skip to content

Commit 020b294

Browse files
mfulbmfulb
committed
more debugging
1 parent 7db674d commit 020b294

File tree

3 files changed

+34
-21
lines changed

3 files changed

+34
-21
lines changed

‎agent/php_observer.c‎

Lines changed: 12 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -117,20 +117,25 @@ static zend_observer_fcall_handlers nr_php_fcall_register_handlers(
117117

118118
// DEBUG: Log ALL function lookups initially to verify Observer is working
119119
static int debug_count = 0;
120-
if (debug_count < 20) {
121-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR OBSERVER DEBUG] Looking up function: %s (count=%d)",
122-
func_name ? ZSTR_VAL(func_name) : "<NULL>", debug_count++);
120+
if (debug_count < 200) {
121+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR OBSERVER DEBUG] Looking up function: %s (count=%d)",
122+
__func__, __LINE__, func_name ? ZSTR_VAL(func_name) : "<NULL>", debug_count++);
123123
}
124124

125125
// DEBUG: Log lookups for add_filter and apply_filters
126126
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
127-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR OBSERVER] Looking up %s in hashmap", ZSTR_VAL(func_name));
127+
nrl_verbosedebug(
128+
NRL_FRAMEWORK,
129+
"[%s:%d NR OBSERVER] Looking up %s (is_method=%d, scope=%s) in hashmap",
130+
__func__, __LINE__, ZSTR_VAL(func_name), scope_name ? 1 : 0,
131+
scope_name ? ZSTR_VAL(scope_name) : "<NULL>");
128132
}
129133

130134
nruserfn_t* wr = nr_php_user_instrument_wraprec_hashmap_get(func_name, scope_name);
131135

132136
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
133-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR OBSERVER] %s lookup result: %s", ZSTR_VAL(func_name), wr ? "FOUND" : "NOT FOUND");
137+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR OBSERVER] %s lookup result: %s",
138+
__func__, __LINE__, ZSTR_VAL(func_name), wr ? "FOUND" : "NOT FOUND");
134139
}
135140

136141
// store the wraprec in the op_array extension for the duration of the request for later lookup
@@ -140,8 +145,8 @@ static zend_observer_fcall_handlers nr_php_fcall_register_handlers(
140145
zend_string* func_name = NR_OP_ARRAY->function_name;
141146
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
142147
nruserfn_t* cached_wr = ZEND_OP_ARRAY_EXTENSION(NR_OP_ARRAY, NR_PHP_PROCESS_GLOBALS(op_array_extension_handle));
143-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR OBSERVER] %s using CACHED wraprec: %s",
144-
ZSTR_VAL(func_name), cached_wr ? "FOUND" : "NULL");
148+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR OBSERVER] %s using CACHED wraprec: %s",
149+
__func__, __LINE__, ZSTR_VAL(func_name), cached_wr ? "FOUND" : "NULL");
145150
}
146151
}
147152

‎agent/php_user_instrument.c‎

Lines changed: 10 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -195,9 +195,9 @@ static inline nruserfn_t* nr_php_wraprec_lookup_get(zend_function* zf) {
195195
|| nr_strstr(func_name, "pre_post_update"))) {
196196
nrl_verbosedebug(
197197
NRL_FRAMEWORK,
198-
"[NR WP LOOKUP PHP8] Function %s on thread %p: RUN_TIME_CACHE=%p, "
198+
"[%s:%d NR WP LOOKUP PHP8] Function %s on thread %p: RUN_TIME_CACHE=%p, "
199199
"wraprec=%p, magic=%s",
200-
func_name ? func_name : "<NULL>", (void*)pthread_self(),
200+
__func__, __LINE__, func_name ? func_name : "<NULL>", (void*)pthread_self(),
201201
(void*)RUN_TIME_CACHE(&zf->op_array), (void*)wraprec,
202202
wraprec ? (wraprec->magic == NR_USERFN_T_MAGIC ? "VALID" : "INVALID")
203203
: "N/A");
@@ -237,8 +237,8 @@ static inline void nr_php_wraprec_lookup_set(nruserfn_t* wr,
237237
if (func_name && (nr_strstr(func_name, "bbp_") || nr_strstr(func_name, "pre_post_update"))) {
238238
nrl_verbosedebug(
239239
NRL_FRAMEWORK,
240-
"[NR WP SET] Storing %s on thread %p: wraprec=%p in hashmap=%p (elements before=%zu)",
241-
func_name ? func_name : "<NULL>",
240+
"[%s:%d NR WP SET] Storing %s on thread %p: wraprec=%p in hashmap=%p (elements before=%zu)",
241+
__func__, __LINE__, func_name ? func_name : "<NULL>",
242242
(void*)pthread_self(),
243243
(void*)wr,
244244
(void*)user_function_wrappers,
@@ -255,8 +255,8 @@ static inline void nr_php_wraprec_lookup_set(nruserfn_t* wr,
255255
if (func_name && (nr_strstr(func_name, "bbp_") || nr_strstr(func_name, "pre_post_update"))) {
256256
nrl_verbosedebug(
257257
NRL_FRAMEWORK,
258-
"[NR WP SET] Stored %s: hashmap now has %zu elements",
259-
func_name ? func_name : "<NULL>",
258+
"[%s:%d NR WP SET] Stored %s: hashmap now has %zu elements",
259+
__func__, __LINE__, func_name ? func_name : "<NULL>",
260260
user_function_wrappers ? user_function_wrappers->elements : 0);
261261
}
262262
nr_free(func_name);
@@ -273,8 +273,8 @@ static inline nruserfn_t* nr_php_wraprec_lookup_get(zend_function* zf) {
273273
if (func_name && (nr_strstr(func_name, "bbp_") || nr_strstr(func_name, "pre_post_update"))) {
274274
nrl_verbosedebug(
275275
NRL_FRAMEWORK,
276-
"[NR WP LOOKUP] Function %s on thread %p: wraprec %s (hashmap=%p, elements=%zu)",
277-
func_name ? func_name : "<NULL>",
276+
"[%s:%d NR WP LOOKUP] Function %s on thread %p: wraprec %s (hashmap=%p, elements=%zu)",
277+
__func__, __LINE__, func_name ? func_name : "<NULL>",
278278
(void*)pthread_self(),
279279
wraprec ? "FOUND" : "NOT FOUND",
280280
(void*)user_function_wrappers,
@@ -304,7 +304,8 @@ void nr_php_init_user_instrumentation(void) {
304304
= nr_php_wraprec_hashmap_create_buckets(1024, reset_wraprec);
305305
nrl_verbosedebug(
306306
NRL_INSTRUMENT,
307-
"[NR HASHMAP] Initialized wraprec hashmap=%p on thread %p",
307+
"[%s:%d NR HASHMAP] Initialized wraprec hashmap=%p on thread %p",
308+
__func__, __LINE__,
308309
(void*)user_function_wrappers,
309310
(void*)pthread_self());
310311
}

‎agent/php_user_instrument_wraprec_hashmap.c‎

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -449,8 +449,8 @@ nruserfn_t* nr_php_user_instrument_wraprec_hashmap_get(zend_string *func_name, z
449449

450450
if (NULL == NRPRG(scope_ht) || NULL == NRPRG(global_funcs_ht)) {
451451
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
452-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR HASHMAP GET] %s: hashmaps are NULL (scope_ht=%p, global_funcs_ht=%p)",
453-
ZSTR_VAL(func_name), (void*)NRPRG(scope_ht), (void*)NRPRG(global_funcs_ht));
452+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR HASHMAP GET] %s: hashmaps are NULL (scope_ht=%p, global_funcs_ht=%p)",
453+
__func__, __LINE__, ZSTR_VAL(func_name), (void*)NRPRG(scope_ht), (void*)NRPRG(global_funcs_ht));
454454
}
455455
return NULL;
456456
}
@@ -470,7 +470,7 @@ nruserfn_t* nr_php_user_instrument_wraprec_hashmap_get(zend_string *func_name, z
470470

471471
if (NULL == funcs_ht) {
472472
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
473-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR HASHMAP GET] %s: funcs_ht is NULL after lookup", ZSTR_VAL(func_name));
473+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR HASHMAP GET] %s: funcs_ht is NULL after lookup", __func__, __LINE__, ZSTR_VAL(func_name));
474474
}
475475
return NULL;
476476
}
@@ -479,11 +479,18 @@ nruserfn_t* nr_php_user_instrument_wraprec_hashmap_get(zend_string *func_name, z
479479
func_key.name_len = ZSTR_LEN(func_name);
480480
func_key.name_hash = ZSTR_HASH(func_name);
481481

482+
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
483+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR HASHMAP GET] %s: is_method=%d, scope=%s, hash=%lu",
484+
__func__, __LINE__, ZSTR_VAL(func_name), func_key.is_method,
485+
scope_name ? ZSTR_VAL(scope_name) : "<NULL>",
486+
func_key.name_hash);
487+
}
488+
482489
result = nr_func_hashmap_lookup_internal(funcs_ht, &func_key);
483490

484491
if (func_name && (0 == strcmp(ZSTR_VAL(func_name), "add_filter") || 0 == strcmp(ZSTR_VAL(func_name), "apply_filters"))) {
485-
nrl_verbosedebug(NRL_FRAMEWORK, "[NR HASHMAP GET] %s: lookup in funcs_ht=%p returned %s",
486-
ZSTR_VAL(func_name), (void*)funcs_ht, result ? "FOUND" : "NOT FOUND");
492+
nrl_verbosedebug(NRL_FRAMEWORK, "[%s:%d NR HASHMAP GET] %s: lookup in funcs_ht=%p returned %s",
493+
__func__, __LINE__, ZSTR_VAL(func_name), (void*)funcs_ht, result ? "FOUND" : "NOT FOUND");
487494
}
488495

489496
return result;

0 commit comments

Comments
 (0)