#!/usr/sbin/dtrace -s BEGIN { self->once = 0; } /* * RPCs * * TODO: add more decoding of RPC args/results. */ pid$1::idmap_null_1_svc:entry, pid$1::idmap_null_1_svc:return, pid$1::idmap_get_mapped_ids_1_svc:return, pid$1::idmap_list_mappings_1_svc:entry, pid$1::idmap_list_mappings_1_svc:return, pid$1::idmap_list_namerules_1_svc:entry, pid$1::idmap_list_namerules_1_svc:return, pid$1::idmap_update_1_svc:entry, pid$1::idmap_update_1_svc:return, pid$1::idmap_get_prop_1_svc:entry, pid$1::idmap_get_prop_1_svc:return, pid$1::idmap_get_mapped_id_by_name_1_svc:entry, pid$1::idmap_get_mapped_id_by_name_1_svc:return { trace(probename); } /* * idmap_get_mapped_ids_1_svc() * * This is the main RPC, we really want the thread ID and count of * requests. */ pid$1::idmap_get_mapped_ids_1_svc:entry { printf("idmap_get_mapped_id_by_name_1_svc() - batch with %d requests, tid = %d\n", arg0, tid); } /* * First a bunch of probes for the first pass over an ID mapping * request. The operations here are ones that are fast/local or can't * be made asynchronous (e.g., getpwuid_r()). * * The sid2pid_first_pass:entry probes should be replaced with a single * USDT probe. * * There's several of these because of the need to have conditional * behavior. */ pid$1::sid2pid_first_pass:entry { self->statep = arg0; self->req = arg1; self->res = arg2; self->req_flag = *(int *)copyin(self->req, 4); self->req_direction = *(int *)copyin(self->req + 4, 4); self->req_id1_idtype = *(int *)copyin(self->req + 8, 4); self->req_id1_sid_prefixp = *(unsigned int *)copyin(self->req + 12, 4); self->req_id1_sid_rid = *(unsigned int *)copyin(self->req + 16, 4); self->req_id1domainp = *(unsigned int *)copyin(self->req + 20, 4); self->req_id1namep = *(unsigned int *)copyin(self->req + 24, 4); self->req_id1_sid_prefix = ""; self->req_id1domain = ""; self->req_id1name = ""; } pid$1::sid2pid_first_pass:entry /self->req_id1_sid_prefixp != 0/ { self->req_id1_sid_prefix = copyinstr(self->req_id1_sid_prefixp); } pid$1::sid2pid_first_pass:entry /self->req_id1domainp != 0/ { self->req_id1domain = copyinstr(self->req_id1domainp); } pid$1::sid2pid_first_pass:entry /self->req_id1namep != 0/ { self->req_id1name = copyinstr(self->req_id1namep); } pid$1::sid2pid_first_pass:entry { printf("sid2pid_first_pass(%p, req->flag = %x, req->direction = %x, req->id1.idtype = %d, req->id1.sid.prefix = %s, req->id1.sid.rid = %d, req->id1domain = %s, req->id1name = %s, tid = %d\n", self->statep, self->req_flag, self->req_direction, self->req_id1_idtype, self->req_id1_sid_prefix, self->req_id1_sid_rid, self->req_id1domain, self->req_id1name, tid); } pid$1::sid2pid_first_pass:return /arg1 == 0/ { self->res_retcode = *(int *)copyin(self->res, 4); self->res_id_idtype = *(int *)copyin(self->res + 4, 4); self->res_id_pid = *(int *)copyin(self->res + 8, 4); self->req_direction = *(int *)copyin(self->req + 4, 4); printf("sid2pid_first_pass(...) -> retcode = %d, status flags = %x, idtype = %d, id = %d, tid = %d\n", self->res_retcode, self->req_direction, self->res_id_idtype, self->res_id_pid, tid); } pid$1::sid2pid_first_pass:return /arg1 != 0/ { printf("sid2pid_first_pass(...) = %d, tid = %d\n", (int)arg1, tid); } pid$1::sid2pid_first_pass:return { self->statep = 0; } /* Same thing for pid2sid_first_pass() */ pid$1::pid2sid_first_pass:entry { self->statep = arg0; self->req = arg1; self->res = arg2; self->req_flag = *(int *)copyin(self->req, 4); self->req_direction = *(int *)copyin(self->req + 4, 4); self->req_id1_idtype = *(int *)copyin(self->req + 8, 4); self->req_id1_pid = *(unsigned int *)copyin(self->req + 12, 4); self->req_id1namep = *(unsigned int *)copyin(self->req + 24, 4); self->req_id1name = ""; } pid$1::pid2sid_first_pass:entry /self->req_id1namep != 0/ { self->req_id1name = copyinstr(self->req_id1namep); } pid$1::pid2sid_first_pass:entry { printf("pid2sid_first_pass(%p, req->flag = %x, req->direction = %x, req->id1.idtype = %d, req->id1.pid = %d, req->id1name = %s, tid = %d\n", self->statep, self->req_flag, self->req_direction, self->req_id1_idtype, self->req_id1_pid, self->req_id1name, tid); } /* pid2sid_first_pass() return could be much more verbose; see sid2pid above */ pid$1::pid2sid_first_pass:return { self->statep = 0; } /* * Parts of the first pass * * Well-known mappings, local SID mappings and the cache are checked in * the first pass. * * These functions are called from sid2pid_first_pass() and * pid2sid_first_pass(). */ /* Was this a well-known SID? */ pid$1::lookup_wksids_sid2pid:return /arg1 == 0 && self->statep != 0/ { printf("WELL-KNOWN SID: %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_wksids_sid2pid:return /(int)arg1 == -9977 && self->statep != 0/ { printf("SID %s-%d NOT a well-known SID, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_wksids_sid2pid:return /arg1 != 0 && (int)arg1 != -9977 && self->statep != 0/ { printf("ERROR %d WHILE CHECKING WK MAPPING FOR SID %s-%d, tid = %d\n", (int)arg1, self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_wksids_pid2sid:return /arg1 == 0 && self->statep != 0/ { printf("POSIX ID %d (type %d) MAPPED TO WELL-KNOWN SID, tid = %d\n", self->req_id1_pid, self->req_id1_idtype, tid); } pid$1::lookup_wksids_pid2sid:return /(int)arg1 == -9977 && self->statep != 0/ { printf("POSIX ID %d (type %d) NOT mapped to well-known SID, tid = %d\n", self->req_id1_pid, self->req_id1_idtype, tid); } pid$1::lookup_wksids_pid2sid:return /arg1 != 0 && (int)arg1 != -9977 && self->statep != 0/ { printf("ERROR %d WHILE CHECKING WK MAPPING FOR POSIX ID %d (type %d), tid = %d\n", (int)arg1, self->req_id1_pid, self->req_id1_idtype, tid); } /* Was this a local SID? */ pid$1::lookup_localsid2pid:return /arg1 == 0 && self->statep != 0/ { printf("LOCAL SID: %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_localsid2pid:return /(int)arg1 == -9977 && self->statep != 0/ { printf("NOT A LOCAL SID: %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_localsid2pid:return /arg1 != 0 && (int)arg1 != -9977 && self->statep != 0/ { printf("ERROR %d WHILE CHECKING LOCAL SID MAPPING FOR SID %s-%d, tid = %d\n", (int)arg1, self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } /* Was a mapping for this SID cached? */ pid$1::lookup_cache_sid2pid:return /arg1 == 0 && self->statep != 0/ { printf("CACHED MAPPING: %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_cache_sid2pid:return /(int)arg1 == -9977 && self->statep != 0/ { printf("CACHED MISS WHILE LOOKING FOR SID %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_cache_sid2pid:return /arg1 != 0 && (int)arg1 != -9977 && self->statep != 0/ { printf("ERROR %d WHILE CHECKING CACHE FOR SID %s-%d, tid = %d\n", (int)arg1, self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } pid$1::lookup_cache_pid2sid:return /arg1 == 0 && self->statep != 0/ { printf("CACHED MAPPING FOR POSIX ID %d (type %d), tid = %d\n", self->req_id1_pid, self->req_id1_idtype, tid); } pid$1::lookup_cache_pid2sid:return /(int)arg1 == -9977 && self->statep != 0 && self->req_id1_pid >= 2147483648/ { printf("NO MAPPING FOUND FOR EPHEMERAL POSIX ID %d (type %d), tid = %d\n", self->req_id1_pid, self->req_id1_idtype, tid); } pid$1::lookup_cache_pid2sid:return /(int)arg1 == -9977 && self->statep != 0 && self->req_id1_pid < 2147483648/ { printf("NO MAPPING FOUND FOR POSIX ID %d (type %d), tid = %d\n", self->req_id1_pid, self->req_id1_idtype, tid); } pid$1::lookup_cache_pid2sid:return /arg1 != 0 && (int)arg1 == -9977 && self->statep != 0/ { printf("ERROR %d WHILE CHECKING CACHE FOR POSIX ID %d (type %d), tid = %d\n", (int)arg1, self->req_id1_pid, self->req_id1_idtype, tid); } /* Was this SID mapped to a local SID? */ pid$1::generate_localsid:entry { self->gl_req = arg0; self->gl_res = arg1; printf("MAPPING NON-EPHEMERAL POSIX ID %d (type %d) TO LOCAL SID... (fallback = %d), tid = %d\n", self->req_id1_pid, self->req_id1_idtype, arg2, tid); } pid$1::generate_localsid:return { self->gl_req_id1_idtype = *(int *)copyin(self->gl_req + 8, 4); self->gl_req_id1_pid = *(unsigned int *)copyin(self->gl_req + 12, 4); } pid$1::generate_localsid:return /arg1 != 0/ { printf("generate_localsid(%d (type %d)) = %d, tid = %d\n", self->gl_req_id1_pid, self->gl_req_id1_idtype, (int)arg1, tid); } pid$1::generate_localsid:return /arg1 == 0/ { self->gl_res_id1_idtype = *(int *)copyin(self->gl_res + 4, 4); self->gl_res_id1_sid_prefix = copyinstr((uintptr_t)*(unsigned int *)copyin(self->gl_res + 8, 4)); self->gl_res_id1_sid_rid = *(unsigned int *)copyin(self->gl_res + 12, 4); printf("generate_localsid(%d (type %d)) = %d -> %s-%d (type %d), tid = %d\n", self->gl_req_id1_pid, self->gl_req_id1_idtype, (int)arg1, self->gl_res_id1_sid_prefix, self->gl_res_id1_sid_rid, self->gl_res_id1_idtype, tid); } /* Was this SID mapped to an ephemeral ID? */ pid$1::dynamic_ephemeral_mapping:entry { self->eph_req = arg1; self->eph_res = arg2; self->eph_req_id1_idtype = *(int *)copyin(self->eph_req + 8, 4); self->eph_req_id1_sid_prefix = copyinstr((uintptr_t)*(unsigned int *)copyin(self->eph_req + 12, 4)); self->eph_req_id1_sid_rid = *(unsigned int *)copyin(self->eph_req + 16, 4); } pid$1::dynamic_ephemeral_mapping:return /arg1 == 0/ { self->eph_res_retcode = *(int *)copyin(self->eph_req, 4); self->eph_res_id_idtype = *(int *)copyin(self->eph_req + 4, 4); self->eph_res_id_pid = *(int *)copyin(self->eph_req + 8, 4); printf("dynamic_ephemeral_mapping(%s-%d) = %d -> %d (type %d), tid = %d\n", self->eph_req_id1_sid_prefix, self->eph_req_id1_sid_rid, self->eph_res_retcode, self->eph_res_id_pid, self->eph_res_id_idtype, tid); } pid$1::dynamic_ephemeral_mapping:return /arg1 != 0/ { self->eph_res_retcode = *(int *)copyin(self->eph_req, 4); printf("dynamic_ephemeral_mapping(%s-%d) = %d (retcode %d), tid = %d\n", self->eph_req_id1_sid_prefix, self->eph_req_id1_sid_rid, (int)arg1, self->eph_res_retcode, tid); } /* Was the result of an LDAP lookup for this SID cached? */ pid$1::lookup_name_cache:return /arg1 == 0 && self->statep != 0/ { printf("NAME CACHE HIT: %s-%d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, tid); } /* adutils tracing */ /* Start of SID->name AD lookup */ pid$1::idmap_sid2name_batch_add1:entry { self->sidprefix = copyinstr(arg1); self->rid = *(unsigned int *)copyin(arg2, 4); printf("idmap_sid2name_batch_add1(%s-%d), tid = %d\n", self->sidprefix, self->rid, tid); } /* This is NOT the end of the SID->name AD lookup */ pid$1::idmap_sid2name_batch_add1:return { printf("idmap_sid2name_batch_add1(%s-%d) = %d, tid = %d\n", self->sidprefix, self->rid, (int)arg1, tid); } /* Start of name->SID AD lookup */ pid$1::idmap_name2sid_batch_add1:entry { self->name = copyinstr(arg1); self->domain = copyinstr(arg2); printf("idmap_name2sid_batch_add1(%s@%s), tid = %d\n", self->name, self->domain, tid); } /* This is NOT the end of the name->SID AD lookup */ pid$1::idmap_name2sid_batch_add1:return { printf("idmap_name2sid_batch_add1(%s@%s) = %d, tid = %d\n", self->name, self->domain, (int)arg1, tid); } pid$1::idmap_lookup_batch_end:entry { printf("Waiting for AD lookups to finish, tid = %d\n", tid); self->trace_batch_end = 0; } pid$1::idmap_lookup_batch_end:return { printf("idmap_lookup_batch_end() = %d, tid = %d\n", (int)arg1, tid); self->trace_batch_end = 1; } pid$1::idmap_lookup_release_batch:entry /self->trace_batch_end != 0/ { printf("AD lookup batch abandoned, tid = %d\n", tid); } /* * We can't access arg10 in DTrace... So we root around in arious structs * to get at what we need: * * - the pointer to idmap_q_t struct for this LDAP search * - the pointer to msgid field of that idmap_q_t struct * - the pointer to rc field of that idmap_q_t struct */ pid$1::idmap_batch_add1:entry { self->batch = arg0; self->lastsent = *(unsigned int *)copyin(self->batch + 28, 4); self->qp = self->batch + 60 + (60 * self->lastsent); self->msgidp = self->qp + 52; self->rcpp = self->qp + 48; } pid$1::ldap_search_ext:entry { self->filter = copyinstr(arg3); } pid$1::ldap_search_ext:return { self->msgid = *(unsigned int *)copyin(self->msgidp, 4); printf("ldap_search_ext(%s) = %d -> msgid = %d, tid = %d\n", self->filter, (int)arg1, self->msgid, tid); } pid$1::ldap_result:return { self->ldap_result_rc = arg1; printf("ldap_result() = %d, tid = %d\n", (int)arg1, tid); } pid$1::idmap_batch_add1:return { self->rcp = *(unsigned int *)copyin(self->rcpp, 4); printf("idmap_batch_add1(...) = %d, msgid = %d, tid = %d\n", (int)arg1, self->msgid, tid); } pid$1::ldap_msgid:return { printf("ldap_msgid() = %d, tid = %d\n", arg1, tid); } /* A result entry came back */ pid$1::idmap_quesearchresbymsgid:entry { self->found_msgid = arg1; printf("DS returned an LDAP result entry for msgid #%d, tid = %d\n", arg1, tid); } pid$1::idmap_quesearchresbymsgid:return { printf("idmap_quesearchresbymsgid(%d) = %d, tid = %d\n", self->found_msgid, arg1, tid); } /* No more result entries are coming back for some msgid */ pid$1::idmap_msgid2query:entry { self->found_msgid = arg1; printf("DS LDAP results for msgid #%d DONE, tid = %d\n", arg1, tid); } /* We probably don't need to trace the idmap_bv_*() functions... */ pid$1::idmap_bv_objsid2sidstr:entry { self->obj_res_ridp = arg1; } pid$1::idmap_bv_objsid2sidstr:return /arg1 != 0/ { self->obj_sidprefix = copyinstr(arg1); self->obj_rid = *(unsigned int *)copyin(self->obj_res_ridp, 4); printf("Found SID %s-%d for LDAP search msgid #%d, tid = %d\n", copyinstr(arg1), *(unsigned int *)copyin(self->obj_res_ridp, 4), self->found_msgid, tid); } pid$1::idmap_bv_objsid2sidstr:return /arg1 == 0/ { printf("PARSE ERROR: objectSid attribute for LDAP search result entry msgid #%d, tid = %d\n", self->found_msgid, tid); } /* Set results for some search */ pid$1::idmap_setqresults:entry { self->qres_ecnamep = *(unsigned int *)copyin(arg0, 4); self->qres_edomainp = *(unsigned int *)copyin(arg0 + 4, 4); self->qres_eunixtype = *(unsigned int *)copyin(arg0 + 8, 4); self->qres_ecname = ""; self->qres_edomain = ""; self->qres_san = ""; self->qres_sid = ""; self->qres_rid = (unsigned int)arg5; self->qres_sidtype = (unsigned int)arg6; self->qres_rcp = *(unsigned int *)copyin(arg0 + 48, 4); } pid$1::idmap_setqresults:entry /self->qres_ecnamep/ { self->qres_ecname = copyinstr(self->qres_ecnamep); } pid$1::idmap_setqresults:entry /self->qres_edomainp/ { self->qres_edomain = copyinstr(self->qres_edomainp); } pid$1::idmap_setqresults:entry /arg1 != 0/ { self->qres_san = copyinstr(arg1); } pid$1::idmap_setqresults:entry /arg4 != 0/ { self->qres_sid = copyinstr(arg4); } pid$1::dn2dns:return /arg1 != 0 && self->qres_san != 0/ { self->qres_dom = copyinstr(arg1); } pid$1::idmap_setqresults:return { self->qres_rc = *(int *)copyin(self->qres_rcp, 4); printf("Results for LDAP search msgid #%d: rc = %d, expected_canon_name = %s, expected_domain = %s, sid = %s-%d, canon_name (san) = %s, dom = %s, sid_type = %d, tid = %d\n", self->found_msgid, self->qres_rc, self->qres_ecname, self->qres_edomain, self->qres_sid, self->qres_rid, self->qres_san, self->qres_dom, self->qres_sidtype, tid); } /* Parse a result entry */ pid$1::idmap_get_adobject_batch:return /self->found_msgid != 0 && self->qres_rc != 0/ { printf("Result code for LDAP search msgid #%d: %d, tid = %d\n", self->found_msgid, self->qres_rc, tid); } /* Now back to dbutils.c with the *_second_pass() functions */ pid$1::sid2pid_second_pass:entry { self->statep = arg0; self->unres_mapping = *(unsigned int *)copyin(arg0 + 16, 4); self->req = arg1; self->res = arg2; self->req_flag = *(int *)copyin(self->req, 4); self->req_direction = *(int *)copyin(self->req + 4, 4); self->req_id1_idtype = *(int *)copyin(self->req + 8, 4); self->req_id1_sid_prefixp = *(unsigned int *)copyin(self->req + 12, 4); self->req_id1_sid_rid = *(unsigned int *)copyin(self->req + 16, 4); self->req_id1domainp = *(unsigned int *)copyin(self->req + 20, 4); self->req_id1namep = *(unsigned int *)copyin(self->req + 24, 4); self->req_id1_sid_prefix = ""; self->req_id1domain = ""; self->req_id1name = ""; } pid$1::sid2pid_second_pass:entry /self->once == 0/ { printf("unresolvable_sid_mapping == %d\n", self->unres_mapping); self->once = 1; } pid$1::sid2pid_second_pass:entry /self->req_id1_sid_prefixp != 0/ { self->req_id1_sid_prefix = copyinstr(self->req_id1_sid_prefixp); } pid$1::sid2pid_second_pass:entry /self->req_id1domainp != 0/ { self->req_id1domain = copyinstr(self->req_id1domainp); } pid$1::sid2pid_second_pass:entry /self->req_id1namep != 0/ { self->req_id1name = copyinstr(self->req_id1namep); } pid$1::sid2pid_second_pass:entry { printf("sid2pid_second_pass(%p, req->flag = %x, req->direction = %x, req->id1.idtype = %d, req->id1.sid.prefix = %s, req->id1.sid.rid = %d, req->id1domain = %s, req->id1name = %s, tid = %d\n", self->statep, self->req_flag, self->req_direction, self->req_id1_idtype, self->req_id1_sid_prefix, self->req_id1_sid_rid, self->req_id1domain, self->req_id1name, tid); self->statep = 0; } pid$1::sid2pid_second_pass:return { self->statep = 0; } pid$1::pid2sid_second_pass:entry { self->statep = arg0; self->req = arg1; self->res = arg2; self->req_flag = *(int *)copyin(self->req, 4); self->req_direction = *(int *)copyin(self->req + 4, 4); self->req_id1_idtype = *(int *)copyin(self->req + 8, 4); self->req_id1_pid = *(unsigned int *)copyin(self->req + 12, 4); self->req_id1namep = *(unsigned int *)copyin(self->req + 24, 4); self->req_id1name = ""; } pid$1::pid2sid_second_pass:entry /self->req_id1namep != 0/ { self->req_id1name = copyinstr(self->req_id1namep); } pid$1::pid2sid_second_pass:entry { printf("pid2sid_second_pass(%p, req->flag = %x, req->direction = %x, req->id1.idtype = %d, req->id1.pid = %d, req->id1name = %s, tid = %d\n", self->statep, self->req_flag, self->req_direction, self->req_id1_idtype, self->req_id1_pid, self->req_id1name, tid); } pid$1::pid2sid_second_pass:return /arg1 == 0/ { self->res_retcode = *(int *)copyin(self->res, 4); self->res_id_idtype = *(int *)copyin(self->res + 4, 4); self->res_id_pid = *(int *)copyin(self->res + 8, 4); printf("sid2pid_first_pass(...) = 0 -> retcode = %d, idtype = %d, id = %d, tid = %d\n", self->res_retcode, self->res_id_idtype, self->res_id_pid, tid); } pid$1::pid2sid_second_pass:return /arg1 != 0/ { printf("sid2pid_first_pass(...) = %d, tid = %d\n", (int)arg1, tid); } pid$1::pid2sid_second_pass:return { self->statep = 0; } /* Name-based mapping. TODO: this needs a lot more tracing! */ pid$1::name_based_mapping_sid2pid:return { printf("name_based_mapping_sid2pid(%s-%d) = %d, tid = %d\n", self->req_id1_sid_prefix, self->req_id1_sid_rid, (int)arg1, tid); } /* TODO: DS-based mapping */ /* TODO: SQLite2 tracing */