ims_charging: add structured debug logging for key functions

src/modules/ims_charging/Ro_data.c

@@ -93,6 +93,8 @@ ims_information_t * new_ims_information(event_type_t * event_type, time_stamps_t
     ims_information_t *x = 0;
     ioi_list_element_t * ioi_elem = 0;
 
+    LM_DBG("create new IMS information\n");
+
     mem_new(x, sizeof (ims_information_t), pkg);
 
     x->event_type = event_type;
@@ -115,8 +117,9 @@ ims_information_t * new_ims_information(event_type_t * event_type, time_stamps_t
         WL_APPEND(&(x->calling_party_address), sl);
     }
 
-    if (called_party && called_party->s)
+    if (called_party && called_party->s) {
         str_dup_ptr(x->called_party_address, *called_party, pkg);
+    }
     
     if (incoming_trunk_id && incoming_trunk_id->s)
         str_dup_ptr(x->incoming_trunk_id, *incoming_trunk_id, pkg);
@@ -154,6 +157,7 @@ service_information_t * new_service_information(ims_information_t * ims_info, su
     service_information_t * x = 0;
     subscription_id_list_element_t * sl = 0;
 
+    LM_DBG("create new service information\n");
     mem_new(x, sizeof (service_information_t), pkg);
 
     x->ims_information = ims_info;
@@ -177,7 +181,7 @@ Ro_CCR_t * new_Ro_CCR(int32_t acc_record_type, str * user_name, ims_information_
     Ro_CCR_t *x = 0;
 
     service_information_t * service_info = 0;
-
+    LM_DBG("create new Ro CCR\n");
     mem_new(x, sizeof (Ro_CCR_t), pkg);
 
     if (cfg.origin_host.s && cfg.origin_host.len > 0)
@@ -198,9 +202,11 @@ Ro_CCR_t * new_Ro_CCR(int32_t acc_record_type, str * user_name, ims_information_
     if (cfg.service_context_id && cfg.service_context_id->s)
         str_dup_ptr(x->service_context_id, *(cfg.service_context_id), pkg);
 
-    if (ims_info)
+    if (ims_info) {
         if (!(service_info = new_service_information(ims_info, subscription)))
             goto error;
+        LM_DBG("Created service information\n");
+    }
 
     x->service_information = service_info;
     service_info = 0;

src/modules/ims_charging/ccr.c

@@ -11,6 +11,7 @@ extern struct cdp_binds cdpb;
 int Ro_write_event_type_avps(AAA_AVP_LIST * avp_list, event_type_t * x) {
     AAA_AVP_LIST aList = {0, 0};
 
+    LM_DBG("write event type AVPs\n");
     if (x->sip_method) {
         if (!cdp_avp->epcapp.add_SIP_Method(&aList, *(x->sip_method), AVP_DUPLICATE_DATA))
             goto error;
@@ -37,6 +38,7 @@ error:
 int Ro_write_time_stamps_avps(AAA_AVP_LIST * avp_list, time_stamps_t* x) {
     AAA_AVP_LIST aList = {0, 0};
 
+    LM_DBG("write timestamp AVPs\n");
     if (x->sip_request_timestamp)
         if (!cdp_avp->epcapp.add_SIP_Request_Timestamp(&aList, *(x->sip_request_timestamp)))
             goto error;
@@ -74,6 +76,8 @@ int Ro_write_ims_information_avps(AAA_AVP_LIST * avp_list, ims_information_t* x)
     service_specific_info_list_element_t * info = 0;
     ioi_list_element_t * ioi_elem = 0;
 
+    LM_DBG("write IMS information AVPs\n");
+
     if (x->event_type)
         if (!Ro_write_event_type_avps(&aList2, x->event_type))
             goto error;
@@ -90,11 +94,15 @@ int Ro_write_ims_information_avps(AAA_AVP_LIST * avp_list, ims_information_t* x)
     for (sl = x->calling_party_address.head; sl; sl = sl->next) {
         if (!cdp_avp->epcapp.add_Calling_Party_Address(&aList2, sl->data, 0))
             goto error;
+        LM_DBG("added calling party address %.*s\n", sl->data.len, sl->data.s);
     }
 
-    if (x->called_party_address)
+    if (x->called_party_address) {
         if (!cdp_avp->epcapp.add_Called_Party_Address(&aList2, *(x->called_party_address), 0))
             goto error;
+        LM_DBG("added called party address %.*s\n",
+                x->called_party_address->len, x->called_party_address->s);
+    }
     
     if (x->incoming_trunk_id && (x->incoming_trunk_id->len > 0) && x->outgoing_trunk_id && (x->outgoing_trunk_id->len > 0)) {
 	if (!cdp_avp->epcapp.add_Outgoing_Trunk_Group_Id(&aList, *(x->outgoing_trunk_id), 0))
@@ -176,7 +184,7 @@ error:
     /*free aList*/
     cdp_avp->cdp->AAAFreeAVPList(&aList);
     cdp_avp->cdp->AAAFreeAVPList(&aList2);
-    LM_ERR("could not add ims information avps\n");
+    LM_ERR("could not add ims information AVPs\n");
     return 0;
 }
 
@@ -184,6 +192,7 @@ int Ro_write_service_information_avps(AAA_AVP_LIST * avp_list, service_informati
     subscription_id_list_element_t * elem = 0;
     AAA_AVP_LIST aList = {0, 0};
 
+    LM_DBG("write service information\n");
     for (elem = x->subscription_id.head; elem; elem = elem->next) {
 
         if (!cdp_avp->ccapp.add_Subscription_Id_Group(&aList, elem->s.type, elem->s.id, 0))
@@ -207,6 +216,7 @@ error:
 AAAMessage * Ro_write_CCR_avps(AAAMessage * ccr, Ro_CCR_t* x) {
 
     if (!ccr) return 0;
+    LM_DBG("write all CCR AVPs\n");
 
     if (x->origin_host.s && x->origin_host.len > 0) {
         if (!cdp_avp->base.add_Origin_Host(&(ccr->avpList), x->origin_host, 0)) goto error;
@@ -250,6 +260,7 @@ error:
 AAAMessage *Ro_new_ccr(AAASession * session, Ro_CCR_t * ro_ccr_data) {
 
     AAAMessage * ccr = 0;
+    LM_DBG("create a new CCR\n");
     ccr = cdp_avp->cdp->AAACreateRequest(IMS_Ro, Diameter_CCR, Flag_Proxyable, session);
     if (!ccr) {
         LM_ERR("could not create CCR\n");
@@ -265,6 +276,7 @@ Ro_CCA_t *Ro_parse_CCA_avps(AAAMessage *cca) {
     if (!cca)
         return 0;
 
+    LM_DBG("parse CCA AVPs\n");
     Ro_CCA_t *ro_cca_data = 0;
     mem_new(ro_cca_data, sizeof (Ro_CCR_t), pkg);
     multiple_services_credit_control_t *mscc = 0;

src/modules/ims_charging/ims_ro.c

@@ -147,6 +147,7 @@ int Ro_add_avp_list(AAA_AVP_LIST *list, char *d, int len, int avp_code,
 
 int Ro_add_cc_request(AAAMessage *msg, unsigned int cc_request_type, unsigned int cc_request_number) {
     char x[4];
+    LM_DBG("add cc request %d\n", cc_request_type);
     set_4bytes(x, cc_request_type);
     int success = Ro_add_avp(msg, x, 4, AVP_CC_Request_Type, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
 
@@ -160,6 +161,7 @@ int Ro_add_cc_request(AAAMessage *msg, unsigned int cc_request_type, unsigned in
 int Ro_add_event_timestamp(AAAMessage *msg, time_t now) {
     char x[4];
     str s = {x, 4};
+    LM_DBG("add Event-Timestamp\n");
     uint32_t ntime = htonl(now + EPOCH_UNIX_TO_EPOCH_NTP);
     memcpy(x, &ntime, sizeof (uint32_t));
 
@@ -190,6 +192,7 @@ int Ro_add_user_equipment_info(AAAMessage *msg, unsigned int type, str value) {
 int Ro_add_termination_cause(AAAMessage *msg, unsigned int term_code) {
     char x[4];
     str s = {x, 4};
+    LM_DBG("add termination cause %d\n", term_code);
     uint32_t code = htonl(term_code);
     memcpy(x, &code, sizeof (uint32_t));
 
@@ -199,6 +202,7 @@ int Ro_add_termination_cause(AAAMessage *msg, unsigned int term_code) {
 int Ro_add_vendor_specific_termination_cause(AAAMessage *msg, unsigned int term_code) {
     char x[4];
     str s = {x, 4};
+    LM_DBG("add vendor specific termination cause %d\n", term_code);
     uint32_t code = htonl(term_code);
     memcpy(x, &code, sizeof (uint32_t));
 
@@ -206,6 +210,7 @@ int Ro_add_vendor_specific_termination_cause(AAAMessage *msg, unsigned int term_
 }
 
 int Ro_add_vendor_specific_termination_reason(AAAMessage *msg, str* reason) {
+    LM_DBG("add vendor specific termination reason: %.*s\n", reason->len, reason->s);
     return Ro_add_avp(msg, reason->s, reason->len, VS_TERMREASON, AAA_AVP_FLAG_VENDOR_SPECIFIC, 10, AVP_DUPLICATE_DATA, __FUNCTION__);
 }
 
@@ -217,6 +222,7 @@ int Ro_add_multiple_service_credit_Control_stop(AAAMessage *msg, int used_unit,
     AAA_AVP_LIST used_list, mscc_list;
     str used_group;
 
+    LM_DBG("add multiple service credit control stop, used unit %d\n", used_unit);
     // Add Multiple-Services AVP Indicator
     set_4bytes(x, 1);
     Ro_add_avp(msg, x, 4, AVP_Multiple_Services_Indicator, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
@@ -270,6 +276,7 @@ int Ro_add_multiple_service_credit_Control(AAAMessage *msg, unsigned int request
     mscc_list.head = 0;
     mscc_list.tail = 0;
 
+    LM_DBG("add multiple service credit control, requested unit %d\n", requested_unit);
     set_4bytes(x, requested_unit);
     Ro_add_avp_list(&list, x, 4, AVP_CC_Time, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
     group = cdpb.AAAGroupAVPS(list);
@@ -310,6 +317,8 @@ int Ro_add_subscription_id(AAAMessage *msg, unsigned int type, str *subscription
     list.head = 0;
     list.tail = 0;
 
+    LM_DBG("add Subscription-Id type %d, id %.*s\n", type, subscription_id->len, subscription_id->s);
+
     set_4bytes(x, type);
     Ro_add_avp_list(&list, x, 4, AVP_Subscription_Id_Type, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
 
@@ -338,14 +347,18 @@ int Ro_add_vendor_specific_appid(AAAMessage *msg, unsigned int vendor_id, unsign
     list.head = 0;
     list.tail = 0;
 
+    LM_DBG("add Vendor-Specific-Application-Id %d\n", vendor_id);
+
     set_4bytes(x, vendor_id);
     Ro_add_avp_list(&list, x, 4, AVP_Vendor_Id, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
 
     if (auth_id) {
+        LM_DBG("adding Auth-Application-Id %d\n", auth_id);
         set_4bytes(x, auth_id);
         Ro_add_avp_list(&list, x, 4, AVP_Auth_Application_Id, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
     }
     if (acct_id) {
+        LM_DBG("adding Acct-Application-Id %d\n", acct_id);
         set_4bytes(x, acct_id);
         Ro_add_avp_list(&list, x, 4, AVP_Acct_Application_Id, AAA_AVP_FLAG_MANDATORY, 0, AVP_DUPLICATE_DATA, __FUNCTION__);
     }
@@ -468,10 +481,10 @@ Ro_CCR_t * dlg_create_ro_session(struct sip_msg * req, struct sip_msg * reply, A
     if (!(ims_info = new_ims_information(event_type, time_stamps, &callid, &callid, &asserted_identity, &called_asserted_identity, &icid,
             &orig_ioi, &term_ioi, dir, incoming_trunk_id, outgoing_trunk_id, pani)))
         goto error;
+    LM_DBG("created IMS information\n");
     event_type = 0;
     time_stamps = 0;
 
-
     subscr.id.s = subscription_id.s;
     subscr.id.len = subscription_id.len;
     subscr.type = subscription_id_type;
@@ -576,7 +589,7 @@ void send_ccr_interim(struct ro_session* ro_session, unsigned int used, unsigned
             &ro_session->called_asserted_identity, 0, 0, 0, ro_session->direction, &ro_session->incoming_trunk_id, &ro_session->outgoing_trunk_id, &ro_session->pani)))
         goto error;
 
-    LM_DBG("Created IMS information\n");
+    LM_DBG("created IMS information\n");
 
     event_type = 0;
 
@@ -1163,6 +1176,7 @@ int Ro_Send_CCR(struct sip_msg *msg, struct dlg_cell *dlg, int dir, int reservat
         LM_ERR("Couldn't create new Ro Session - this is BAD!\n");
         goto error;
     }
+    LM_DBG("new session created\n");
 
     ssd->action = action;
     ssd->tindex = tindex;