diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/libmsc/gsm_04_08_cc.c | 194 | ||||
| -rw-r--r-- | src/libmsc/gsm_04_11.c | 178 | ||||
| -rw-r--r-- | src/libmsc/gsm_04_11_gsup.c | 15 | ||||
| -rw-r--r-- | src/libmsc/gsm_09_11.c | 70 | ||||
| -rw-r--r-- | src/libmsc/transaction.c | 11 |
5 files changed, 205 insertions, 263 deletions
diff --git a/src/libmsc/gsm_04_08_cc.c b/src/libmsc/gsm_04_08_cc.c index 532472e42..4475d0503 100644 --- a/src/libmsc/gsm_04_08_cc.c +++ b/src/libmsc/gsm_04_08_cc.c @@ -75,8 +75,7 @@ static uint32_t new_callref = 0x80000001; static void gsm48_cc_guard_timeout(void *arg) { struct gsm_trans *trans = arg; - DEBUGP(DCC, "(sub %s) guard timeout expired\n", - vlr_subscr_msisdn_or_name(trans->vsub)); + LOG_TRANS(trans, LOGL_DEBUG, "guard timeout expired\n"); trans_free(trans); return; } @@ -84,8 +83,7 @@ static void gsm48_cc_guard_timeout(void *arg) static void gsm48_stop_guard_timer(struct gsm_trans *trans) { if (osmo_timer_pending(&trans->cc.timer_guard)) { - DEBUGP(DCC, "(sub %s) stopping pending guard timer\n", - vlr_subscr_msisdn_or_name(trans->vsub)); + LOG_TRANS(trans, LOGL_DEBUG, "stopping pending guard timer\n"); osmo_timer_del(&trans->cc.timer_guard); } } @@ -102,9 +100,7 @@ static void gsm48_start_guard_timer(struct gsm_trans *trans) * timer will time out and hard-clear the connection. */ if (osmo_timer_pending(&trans->cc.timer_guard)) gsm48_stop_guard_timer(trans); - DEBUGP(DCC, "(sub %s) starting guard timer with %d seconds\n", - vlr_subscr_msisdn_or_name(trans->vsub), - trans->net->mncc_guard_timeout); + LOG_TRANS(trans, LOGL_DEBUG, "starting guard timer with %d seconds\n", trans->net->mncc_guard_timeout); osmo_timer_setup(&trans->cc.timer_guard, gsm48_cc_guard_timeout, trans); osmo_timer_schedule(&trans->cc.timer_guard, trans->net->mncc_guard_timeout, 0); @@ -177,11 +173,9 @@ static void new_cc_state(struct gsm_trans *trans, int state) if (state > 31 || state < 0) return; - DEBUGP(DCC, "(ti %02x sub %s) new state %s -> %s\n", - trans->transaction_id, - vlr_subscr_name(trans->vsub), - gsm48_cc_state_name(trans->cc.state), - gsm48_cc_state_name(state)); + LOG_TRANS(trans, LOGL_DEBUG, "new state %s -> %s\n", + gsm48_cc_state_name(trans->cc.state), + gsm48_cc_state_name(state)); count_statistics(trans, state); trans->cc.state = state; @@ -213,7 +207,7 @@ static int gsm48_cc_tx_status(struct gsm_trans *trans, void *arg) static void gsm48_stop_cc_timer(struct gsm_trans *trans) { if (osmo_timer_pending(&trans->cc.timer)) { - DEBUGP(DCC, "stopping pending timer T%x\n", trans->cc.Tcurrent); + LOG_TRANS(trans, LOGL_DEBUG, "stopping pending timer T%x\n", trans->cc.Tcurrent); osmo_timer_del(&trans->cc.timer); trans->cc.Tcurrent = 0; } @@ -225,31 +219,7 @@ static int mncc_recvmsg(struct gsm_network *net, struct gsm_trans *trans, struct msgb *msg; unsigned char *data; - DEBUGP(DMNCC, "transmit message %s\n", get_mncc_name(msg_type)); - -#if BEFORE_MSCSPLIT - /* Re-enable this log output once we can obtain this information via - * A-interface, see OS#2391. */ - if (trans) - if (trans->conn && trans->conn->lchan) - DEBUGP(DCC, "(bts %d trx %d ts %d ti %x sub %s) " - "Sending '%s' to MNCC.\n", - trans->conn->lchan->ts->trx->bts->nr, - trans->conn->lchan->ts->trx->nr, - trans->conn->lchan->ts->nr, trans->transaction_id, - vlr_subscr_msisdn_or_name(trans->vsub), - get_mncc_name(msg_type)); - else - DEBUGP(DCC, "(bts - trx - ts - ti -- sub %s) " - "Sending '%s' to MNCC.\n", - vlr_subscr_msisdn_or_name(trans->vsub), - get_mncc_name(msg_type)); - else - DEBUGP(DCC, "(bts - trx - ts - ti -- sub -) " - "Sending '%s' to MNCC.\n", get_mncc_name(msg_type)); -#else - DEBUGP(DCC, "Sending '%s' to MNCC.\n", get_mncc_name(msg_type)); -#endif + LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "tx %s\n", get_mncc_name(msg_type)); mncc->msg_type = msg_type; @@ -317,8 +287,7 @@ static int setup_trig_pag_evt(unsigned int hooknum, unsigned int event, switch (paging_event) { case GSM_PAGING_SUCCEEDED: - DEBUGP(DCC, "Paging subscr %s succeeded!\n", - vlr_subscr_msisdn_or_name(transt->vsub)); + LOG_TRANS(transt, LOGL_DEBUG, "Paging succeeded\n"); OSMO_ASSERT(conn); /* Assign conn */ transt->conn = ran_conn_get(conn, RAN_CONN_USE_TRANS_CC); @@ -328,9 +297,7 @@ static int setup_trig_pag_evt(unsigned int hooknum, unsigned int event, break; case GSM_PAGING_EXPIRED: case GSM_PAGING_BUSY: - DEBUGP(DCC, "Paging subscr %s %s!\n", - vlr_subscr_msisdn_or_name(transt->vsub), - paging_event == GSM_PAGING_EXPIRED ? "expired" : "busy"); + LOG_TRANS(transt, LOGL_DEBUG, "Paging expired\n"); /* Temporarily out of order */ mncc_release_ind(transt->net, transt, transt->callref, @@ -352,11 +319,19 @@ static int tch_bridge(struct gsm_network *net, struct gsm_mncc_bridge *bridge) struct gsm_trans *trans2 = trans_find_by_callref(net, bridge->callref[1]); int rc; - if (!trans1 || !trans2) + if (!trans1 || !trans2) { + LOG_TRANS(trans1 ? : trans2, LOGL_ERROR, "Cannot MNCC_BRIDGE, one or both call legs are unset\n"); return -EIO; + } - if (!trans1->conn || !trans2->conn) + if (!trans1->conn || !trans2->conn) { + LOG_TRANS(trans1, LOGL_ERROR, "Cannot MNCC_BRIDGE, one or both call legs lack an active connection\n"); + LOG_TRANS(trans2, LOGL_ERROR, "Cannot MNCC_BRIDGE, one or both call legs lack an active connection\n"); return -EIO; + } + + LOG_TRANS(trans1, LOGL_DEBUG, "MNCC_BRIDGE: Local bridge to callref 0x%x\n", trans2->callref); + LOG_TRANS(trans2, LOGL_DEBUG, "MNCC_BRIDGE: Local bridge to callref 0x%x\n", trans1->callref); /* Which subscriber do we want to track trans1 or trans2? */ log_set_context(LOG_CTX_VLR_SUBSCR, trans1->vsub); @@ -386,7 +361,7 @@ static int tch_bridge(struct gsm_network *net, struct gsm_mncc_bridge *bridge) static int gsm48_cc_rx_status_enq(struct gsm_trans *trans, struct msgb *msg) { - DEBUGP(DCC, "-> STATUS ENQ\n"); + LOG_TRANS(trans, LOGL_DEBUG, "-> STATUS ENQ\n"); return gsm48_cc_tx_status(trans, msg); } @@ -485,7 +460,9 @@ static inline void disconnect_bridge(struct gsm_network *net, if (!trans0 || !trans1) return; - DEBUGP(DCC, "Failed to bridge TCH for calls %x <-> %x :: %s \n", + LOG_TRANS(trans0, LOGL_ERROR, "Failed to bridge TCH for calls %x <-> %x :: %s \n", + trans0->callref, trans1->callref, strerror(err)); + LOG_TRANS(trans1, LOGL_ERROR, "Failed to bridge TCH for calls %x <-> %x :: %s \n", trans0->callref, trans1->callref, strerror(err)); memset(&mx_rel, 0, sizeof(struct gsm_mncc)); @@ -502,7 +479,7 @@ static inline void disconnect_bridge(struct gsm_network *net, static void gsm48_start_cc_timer(struct gsm_trans *trans, int current, int sec, int micro) { - DEBUGP(DCC, "starting timer T%x with %d seconds\n", current, sec); + LOG_TRANS(trans, LOGL_DEBUG, "starting timer T%x with %d seconds\n", current, sec); osmo_timer_setup(&trans->cc.timer, gsm48_cc_timeout, trans); osmo_timer_schedule(&trans->cc.timer, sec, micro); trans->cc.Tcurrent = current; @@ -592,9 +569,8 @@ static int gsm48_cc_rx_setup(struct gsm_trans *trans, struct msgb *msg) new_cc_state(trans, GSM_CSTATE_INITIATED); - LOGP(DCC, setup.emergency ? LOGL_NOTICE : LOGL_INFO, "Subscriber %s (%s) sends %sSETUP to %s\n", - vlr_subscr_name(trans->vsub), trans->vsub->msisdn, setup.emergency ? "EMERGENCY_" : "", - setup.called.number); + LOG_TRANS(trans, setup.emergency ? LOGL_NOTICE : LOGL_INFO, "%sSETUP to %s\n", + setup.emergency ? "EMERGENCY_" : "", setup.called.number); rate_ctr_inc(&trans->net->msc_ctrs->ctr[MSC_CTR_CALL_MO_SETUP]); @@ -618,7 +594,7 @@ static int gsm48_cc_tx_setup(struct gsm_trans *trans, void *arg) /* transaction id must not be assigned */ if (trans->transaction_id != TRANS_ID_UNASSIGNED) { - DEBUGP(DCC, "TX Setup with assigned transaction. " + LOG_TRANS(trans, LOGL_DEBUG, "TX Setup with assigned transaction. " "This is not allowed!\n"); /* Temporarily out of order */ rc = mncc_release_ind(trans->net, trans, trans->callref, @@ -1695,13 +1671,13 @@ static int tch_rtp_create(struct gsm_network *net, uint32_t callref) /* Find callref */ trans = trans_find_by_callref(net, callref); if (!trans) { - LOGP(DMNCC, LOGL_ERROR, "RTP create for non-existing trans\n"); + LOG_TRANS_CAT(trans, DMNCC, LOGL_ERROR, "RTP create for non-existing trans\n"); mncc_recv_rtp_err(net, callref, MNCC_RTP_CREATE); return -EIO; } log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); if (!trans->conn) { - LOGP(DMNCC, LOGL_NOTICE, "RTP create for trans without conn\n"); + LOG_TRANS_CAT(trans, DMNCC, LOGL_NOTICE, "RTP create for trans without conn\n"); mncc_recv_rtp_err(net, callref, MNCC_RTP_CREATE); return 0; } @@ -1756,13 +1732,13 @@ static int tch_rtp_connect(struct gsm_network *net, struct gsm_mncc_rtp *rtp) /* Find callref */ trans = trans_find_by_callref(net, rtp->callref); if (!trans) { - LOGP(DMNCC, LOGL_ERROR, "RTP connect for non-existing trans\n"); + LOG_TRANS_CAT(trans, DMNCC, LOGL_ERROR, "RTP connect for non-existing trans\n"); mncc_recv_rtp_err(net, rtp->callref, MNCC_RTP_CONNECT); return -EIO; } log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); if (!trans->conn) { - LOGP(DMNCC, LOGL_ERROR, "RTP connect for trans without conn\n"); + LOG_TRANS_CAT(trans, DMNCC, LOGL_ERROR, "RTP connect for trans without conn\n"); mncc_recv_rtp_err(net, rtp->callref, MNCC_RTP_CONNECT); return 0; } @@ -1837,8 +1813,6 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) struct ran_conn *conn = NULL; struct gsm_mncc *data = arg, rel; - DEBUGP(DMNCC, "receive message %s\n", get_mncc_name(msg_type)); - /* handle special messages */ switch(msg_type) { case MNCC_BRIDGE: @@ -1860,7 +1834,7 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) case GSM_TCHF_FRAME_EFR: case GSM_TCHH_FRAME: case GSM_TCH_FRAME_AMR: - LOGP(DMNCC, LOGL_ERROR, "RTP streams must be handled externally; %s not supported.\n", + LOG_TRANS_CAT(trans, DMNCC, LOGL_ERROR, "RTP streams must be handled externally; %s not supported.\n", get_mncc_name(msg_type)); return -ENOTSUP; } @@ -1876,51 +1850,43 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) struct vlr_subscr *vsub; if (msg_type != MNCC_SETUP_REQ) { - DEBUGP(DCC, "(bts - trx - ts - ti -- sub %s) " - "Received '%s' from MNCC with " - "unknown callref %d\n", data->called.number, - get_mncc_name(msg_type), data->callref); + LOG_TRANS_CAT(trans, DCC, LOGL_ERROR, "Unknown call reference for %s\n", + get_mncc_name(msg_type)); /* Invalid call reference */ return mncc_release_ind(net, NULL, data->callref, GSM48_CAUSE_LOC_PRN_S_LU, GSM48_CC_CAUSE_INVAL_TRANS_ID); } if (!data->called.number[0] && !data->imsi[0]) { - DEBUGP(DCC, "(bts - trx - ts - ti) " - "Received '%s' from MNCC with " - "no number or IMSI\n", get_mncc_name(msg_type)); + LOG_TRANS_CAT(trans, DCC, LOGL_ERROR, "Neither number nor IMSI in %s\n", + get_mncc_name(msg_type)); /* Invalid number */ return mncc_release_ind(net, NULL, data->callref, GSM48_CAUSE_LOC_PRN_S_LU, GSM48_CC_CAUSE_INV_NR_FORMAT); } /* New transaction due to setup, find subscriber */ - if (data->called.number[0]) - vsub = vlr_subscr_find_by_msisdn(net->vlr, - data->called.number, __func__); - else + if (data->called.number[0]) { + vsub = vlr_subscr_find_by_msisdn(net->vlr, data->called.number, __func__); + if (!vsub) + LOG_TRANS_CAT(trans, DCC, LOGL_ERROR, "rx %s for unknown subscriber number '%s'\n", + get_mncc_name(msg_type), data->called.number); + } else { vsub = vlr_subscr_find_by_imsi(net->vlr, data->imsi, __func__); - + if (!vsub) + LOG_TRANS_CAT(trans, DCC, LOGL_ERROR, "rx %s for unknown subscriber IMSI '%s'\n", + get_mncc_name(msg_type), data->imsi); + } + if (!vsub) + return mncc_release_ind(net, NULL, data->callref, GSM48_CAUSE_LOC_PRN_S_LU, + GSM48_CC_CAUSE_UNASSIGNED_NR); /* update the subscriber we deal with */ log_set_context(LOG_CTX_VLR_SUBSCR, vsub); - /* If subscriber is not found */ - if (!vsub) { - DEBUGP(DCC, "(bts - trx - ts - ti -- sub %s) " - "Received '%s' from MNCC with " - "unknown subscriber %s\n", data->called.number, - get_mncc_name(msg_type), data->called.number); - /* Unknown subscriber */ - return mncc_release_ind(net, NULL, data->callref, - GSM48_CAUSE_LOC_PRN_S_LU, - GSM48_CC_CAUSE_UNASSIGNED_NR); - } /* If subscriber is not "attached" */ - if (!vsub->cgi.lai.lac) { - DEBUGP(DCC, "(bts - trx - ts - ti -- sub %s) " - "Received '%s' from MNCC with " - "detached subscriber %s\n", data->called.number, - get_mncc_name(msg_type), vlr_subscr_name(vsub)); + if (!vsub->lu_complete) { + LOG_TRANS_CAT(trans, DCC, LOGL_ERROR, "rx %s for subscriber that is not attached: %s\n", + get_mncc_name(msg_type), vlr_subscr_name(vsub)); vlr_subscr_put(vsub, __func__); /* Temporarily out of order */ return mncc_release_ind(net, NULL, data->callref, @@ -1931,7 +1897,7 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) trans = trans_alloc(net, vsub, GSM48_PDISC_CC, TRANS_ID_UNASSIGNED, data->callref); if (!trans) { - LOGP(DCC, LOGL_ERROR, "No memory for trans.\n"); + LOG_TRANS(trans, LOGL_ERROR, "No memory for trans.\n"); vlr_subscr_put(vsub, __func__); /* Ressource unavailable */ mncc_release_ind(net, NULL, data->callref, @@ -1951,16 +1917,14 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) if (transt == trans || transt->vsub != vsub) continue; - DEBUGP(DCC, "(bts - trx - ts - ti -- sub %s) " - "Received '%s' from MNCC with " - "unallocated channel, paging already " - "started for lac %d.\n", - data->called.number, - get_mncc_name(msg_type), vsub->cgi.lai.lac); + LOG_TRANS(trans, LOGL_DEBUG, + "rx %s, subscriber not yet connected, paging already started\n", + get_mncc_name(msg_type)); vlr_subscr_put(vsub, __func__); trans_free(trans); return 0; } + /* store setup information until paging succeeds */ memcpy(&trans->cc.msg, data, sizeof(struct gsm_mncc)); @@ -1972,7 +1936,7 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) "MNCC: establish call", SGSAP_SERV_IND_CS_CALL); if (!trans->paging_request) { - LOGP(DCC, LOGL_ERROR, "Failed to allocate paging token.\n"); + LOG_TRANS(trans, LOGL_ERROR, "Failed to allocate paging token.\n"); vlr_subscr_put(vsub, __func__); trans_free(trans); return 0; @@ -1990,6 +1954,8 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); } + LOG_TRANS_CAT(trans, DMNCC, LOGL_DEBUG, "rx %s\n", get_mncc_name(msg_type)); + gsm48_start_guard_timer(trans); if (trans->conn) @@ -1997,10 +1963,7 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) /* if paging did not respond yet */ if (!conn) { - DEBUGP(DCC, "(sub %s) " - "Received '%s' from MNCC in paging state\n", - vlr_subscr_msisdn_or_name(trans->vsub), - get_mncc_name(msg_type)); + LOG_TRANS(trans, LOGL_DEBUG, "rx %s in paging state\n", get_mncc_name(msg_type)); mncc_set_cause(&rel, GSM48_CAUSE_LOC_PRN_S_LU, GSM48_CC_CAUSE_NORM_CALL_CLEAR); if (msg_type == MNCC_REL_REQ) @@ -2011,12 +1974,8 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) trans_free(trans); return rc; } else { - DEBUGP(DCC, "(ti %02x sub %s) " - "Received '%s' from MNCC in state %d (%s)\n", - trans->transaction_id, - vlr_subscr_msisdn_or_name(trans->conn->vsub), - get_mncc_name(msg_type), trans->cc.state, - gsm48_cc_state_name(trans->cc.state)); + LOG_TRANS(trans, LOGL_DEBUG, "rx %s in state %s\n", + get_mncc_name(msg_type), gsm48_cc_state_name(trans->cc.state)); } /* Find function for current state and message */ @@ -2025,7 +1984,8 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg) && ((1 << trans->cc.state) & downstatelist[i].states)) break; if (i == DOWNSLLEN) { - DEBUGP(DCC, "Message '%s' unhandled at state '%s'\n", get_mncc_name(msg_type), gsm48_cc_state_name(trans->cc.state)); + LOG_TRANS(trans, LOGL_DEBUG, "Message '%s' unhandled at state '%s'\n", + get_mncc_name(msg_type), gsm48_cc_state_name(trans->cc.state)); return 0; } @@ -2098,29 +2058,18 @@ int gsm0408_rcv_cc(struct ran_conn *conn, struct msgb *msg) int i, rc = 0; if (msg_type & 0x80) { - DEBUGP(DCC, "MSG 0x%2x not defined for PD error\n", msg_type); + LOG_TRANS(trans, LOGL_DEBUG, "MSG 0x%2x not defined for PD error\n", msg_type); return -EINVAL; } if (!conn->vsub) { - LOGP(DCC, LOGL_ERROR, "Invalid conn: no subscriber\n"); + LOG_TRANS(trans, LOGL_ERROR, "Invalid conn: no subscriber\n"); return -EINVAL; } /* Find transaction */ trans = trans_find_by_id(conn, GSM48_PDISC_CC, transaction_id); -#if BEFORE_MSCSPLIT - /* Re-enable this log output once we can obtain this information via - * A-interface, see OS#2391. */ - DEBUGP(DCC, "(bts %d trx %d ts %d ti %x sub %s) " - "Received '%s' from MS in state %d (%s)\n", - conn->bts->nr, conn->lchan->ts->trx->nr, conn->lchan->ts->nr, - transaction_id, vlr_subscr_msisdn_or_name(conn->vsub), - gsm48_cc_msg_name(msg_type), trans?(trans->cc.state):0, - gsm48_cc_state_name(trans?(trans->cc.state):0)); -#endif - /* Create transaction */ if (!trans) { DEBUGP(DCC, "Unknown transaction ID %x, " @@ -2130,7 +2079,7 @@ int gsm0408_rcv_cc(struct ran_conn *conn, struct msgb *msg) GSM48_PDISC_CC, transaction_id, new_callref++); if (!trans) { - LOGP(DCC, LOGL_ERROR, "No memory for trans.\n"); + LOG_TRANS(trans, LOGL_ERROR, "No memory for trans.\n"); rc = gsm48_tx_simple(conn, GSM48_PDISC_CC | (transaction_id << 4), GSM48_MT_CC_RELEASE_COMPL); @@ -2142,13 +2091,16 @@ int gsm0408_rcv_cc(struct ran_conn *conn, struct msgb *msg) cm_service_request_concludes(conn, msg); } + LOG_TRANS(trans, LOGL_DEBUG, "rx %s in state %s\n", gsm48_cc_msg_name(msg_type), + gsm48_cc_state_name(trans->cc.state)); + /* find function for current state and message */ for (i = 0; i < DATASLLEN; i++) if ((msg_type == datastatelist[i].type) && ((1 << trans->cc.state) & datastatelist[i].states)) break; if (i == DATASLLEN) { - DEBUGP(DCC, "Message unhandled at this state.\n"); + LOG_TRANS(trans, LOGL_ERROR, "Message unhandled at this state.\n"); return 0; } diff --git a/src/libmsc/gsm_04_11.c b/src/libmsc/gsm_04_11.c index 37d033310..434f87858 100644 --- a/src/libmsc/gsm_04_11.c +++ b/src/libmsc/gsm_04_11.c @@ -120,11 +120,11 @@ static void send_signal(int sig_no, osmo_signal_dispatch(SS_SMS, sig_no, &sig); } -static int gsm411_sendmsg(struct ran_conn *conn, struct msgb *msg) +static int gsm411_sendmsg(struct gsm_trans *trans, struct msgb *msg) { - DEBUGP(DLSMS, "GSM4.11 TX %s\n", msgb_hexdump(msg)); + LOG_TRANS(trans, LOGL_DEBUG, "GSM4.11 TX %s\n", msgb_hexdump(msg)); msg->l3h = msg->data; - return msc_tx_dtap(conn, msg); + return msc_tx_dtap(trans->conn, msg); } /* Paging callback for MT SMS (Paging is triggered by SMC) */ @@ -136,7 +136,7 @@ static int paging_cb_mmsms_est_req(unsigned int hooknum, unsigned int event, struct gsm_sms *sms = trans->sms.sms; int rc = 0; - DEBUGP(DLSMS, "paging_cb_mmsms_est_req(hooknum=%u, event=%u)\n", hooknum, event); + LOG_TRANS(trans, LOGL_DEBUG, "%s(%s)\n", __func__, event == GSM_PAGING_SUCCEEDED ? "success" : "expired"); if (hooknum != GSM_HOOK_RR_PAGING) return -EINVAL; @@ -184,22 +184,19 @@ static int gsm411_mmsms_est_req(struct gsm_trans *trans) /* Check if connection is already established */ if (trans->conn != NULL) { - LOGP(DLSMS, LOGL_DEBUG, "Using an existing connection " - "for %s\n", vlr_subscr_name(trans->vsub)); + LOG_TRANS(trans, LOGL_DEBUG, "Using an existing connection\n"); return gsm411_smc_recv(&trans->sms.smc_inst, GSM411_MMSMS_EST_CNF, NULL, 0); } /* Initiate Paging procedure */ - LOGP(DLSMS, LOGL_DEBUG, "Initiating Paging procedure " - "for %s due to MMSMS_EST_REQ\n", vlr_subscr_name(trans->vsub)); + LOG_TRANS(trans, LOGL_DEBUG, "Initiating Paging due to MMSMS_EST_REQ\n"); trans->paging_request = subscr_request_conn(trans->vsub, paging_cb_mmsms_est_req, trans, "MT SMS", SGSAP_SERV_IND_SMS); if (!trans->paging_request) { - LOGP(DLSMS, LOGL_ERROR, "Failed to initiate Paging " - "procedure for %s\n", vlr_subscr_name(trans->vsub)); + LOG_TRANS(trans, LOGL_ERROR, "Failed to initiate Paging\n"); /* Inform SMC about channel establishment failure */ gsm411_smc_recv(&trans->sms.smc_inst, GSM411_MMSMS_REL_IND, NULL, 0); @@ -222,9 +219,9 @@ static int gsm411_cp_sendmsg(struct msgb *msg, struct gsm_trans *trans, gh->msg_type = msg_type; OMSC_LINKID_CB(msg) = trans->dlci; - DEBUGP(DLSMS, "sending CP message (trans=%x)\n", trans->transaction_id); + LOG_TRANS(trans, LOGL_DEBUG, "sending CP message (trans=%x)\n", trans->transaction_id); - return gsm411_sendmsg(trans->conn, msg); + return gsm411_sendmsg(trans, msg); } /* mm_send: receive MMCCSMS sap message from SMC */ @@ -244,12 +241,12 @@ static int gsm411_mm_send(struct gsm411_smc_inst *inst, int msg_type, rc = gsm411_cp_sendmsg(msg, trans, cp_msg_type); break; case GSM411_MMSMS_REL_REQ: - DEBUGP(DLSMS, "Got MMSMS_REL_REQ, destroying transaction.\n"); + LOG_TRANS(trans, LOGL_DEBUG, "Got MMSMS_REL_REQ, destroying transaction.\n"); msgb_free(msg); trans_free(trans); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Unhandled MMCCSMS msg 0x%x\n", msg_type); + LOG_TRANS(trans, LOGL_NOTICE, "Unhandled MMCCSMS msg 0x%x\n", msg_type); msgb_free(msg); rc = -EINVAL; } @@ -268,10 +265,10 @@ int gsm411_mn_send(struct gsm411_smr_inst *inst, int msg_type, return gsm411_smc_send(&trans->sms.smc_inst, msg_type, msg); } -static int gsm340_rx_sms_submit(struct gsm_sms *gsms) +static int gsm340_rx_sms_submit(struct gsm_trans *trans, struct gsm_sms *gsms) { if (db_sms_store(gsms) != 0) { - LOGP(DLSMS, LOGL_ERROR, "Failed to store SMS in Database\n"); + LOG_TRANS(trans, LOGL_ERROR, "Failed to store SMS in Database\n"); return GSM411_RP_CAUSE_MO_NET_OUT_OF_ORDER; } /* dispatch a signal to tell higher level about it */ @@ -290,7 +287,7 @@ static int gsm340_gen_oa_sub(uint8_t *oa, unsigned int oa_len, /* generate a msgb containing an 03.40 9.2.2.1 SMS-DELIVER TPDU derived from * struct gsm_sms, returns total size of TPDU */ -static int gsm340_gen_sms_deliver_tpdu(struct msgb *msg, struct gsm_sms *sms) +static int gsm340_gen_sms_deliver_tpdu(struct gsm_trans *trans, struct msgb *msg, struct gsm_sms *sms) { uint8_t *smsp; uint8_t oa[12]; /* max len per 03.40 */ @@ -353,8 +350,8 @@ static int gsm340_gen_sms_deliver_tpdu(struct msgb *msg, struct gsm_sms *sms) memcpy(smsp, sms->user_data, sms->user_data_len); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Unhandled Data Coding Scheme: 0x%02X\n", - sms->data_coding_scheme); + LOG_TRANS(trans, LOGL_NOTICE, "Unhandled Data Coding Scheme: 0x%02X\n", + sms->data_coding_scheme); break; } @@ -362,7 +359,7 @@ static int gsm340_gen_sms_deliver_tpdu(struct msgb *msg, struct gsm_sms *sms) } /* As defined by GSM 03.40, Section 9.2.2.3. */ -static int gsm340_gen_sms_status_report_tpdu(struct msgb *msg, +static int gsm340_gen_sms_status_report_tpdu(struct gsm_trans *trans, struct msgb *msg, struct gsm_sms *sms) { unsigned int old_msg_len = msg->len; @@ -402,16 +399,16 @@ static int gsm340_gen_sms_status_report_tpdu(struct msgb *msg, /* From GSM 03.40, Section 9.2.3.15, 0x00 means OK. */ *smsp = 0x00; - LOGP(DLSMS, LOGL_INFO, "sending status report for SMS reference %x\n", - sms->msg_ref); + LOG_TRANS(trans, LOGL_INFO, "sending status report for SMS reference %x\n", + sms->msg_ref); return msg->len - old_msg_len; } -static int sms_route_mt_sms(struct ran_conn *conn, - struct gsm_sms *gsms) +static int sms_route_mt_sms(struct gsm_trans *trans, struct gsm_sms *gsms) { int rc; + struct ran_conn *conn = trans->conn; #ifdef BUILD_SMPP int smpp_first = smpp_route_smpp_first(gsms, conn); @@ -428,8 +425,7 @@ static int sms_route_mt_sms(struct ran_conn *conn, /* unknown subscriber, try local */ goto try_local; if (rc < 0) { - LOGP(DLSMS, LOGL_ERROR, "%s: SMS delivery error: %d.", - vlr_subscr_name(conn->vsub), rc); + LOG_TRANS(trans, LOGL_ERROR, "SMS delivery error: %d.", rc); rc = GSM411_RP_CAUSE_MO_TEMP_FAIL; /* rc will be logged by gsm411_send_rp_error() */ rate_ctr_inc(&conn->network->msc_ctrs->ctr[ @@ -455,8 +451,7 @@ try_local: if (rc == GSM411_RP_CAUSE_MO_NUM_UNASSIGNED) { rate_ctr_inc(&conn->network->msc_ctrs->ctr[MSC_CTR_SMS_NO_RECEIVER]); } else if (rc < 0) { - LOGP(DLSMS, LOGL_ERROR, "%s: SMS delivery error: %d.", - vlr_subscr_name(conn->vsub), rc); + LOG_TRANS(trans, LOGL_ERROR, "SMS delivery error: %d.", rc); rc = GSM411_RP_CAUSE_MO_TEMP_FAIL; /* rc will be logged by gsm411_send_rp_error() */ rate_ctr_inc(&conn->network->msc_ctrs->ctr[ @@ -515,11 +510,11 @@ static int gsm340_rx_tpdu(struct gsm_trans *trans, struct msgb *msg, /* length in bytes of the destination address */ da_len_bytes = 2 + *smsp/2 + *smsp%2; if (da_len_bytes > 12) { - LOGP(DLSMS, LOGL_ERROR, "Destination Address > 12 bytes ?!?\n"); + LOG_TRANS(trans, LOGL_ERROR, "Destination Address > 12 bytes ?!?\n"); rc = GSM411_RP_CAUSE_SEMANT_INC_MSG; goto out; } else if (da_len_bytes < 4) { - LOGP(DLSMS, LOGL_ERROR, "Destination Address < 4 bytes ?!?\n"); + LOG_TRANS(trans, LOGL_ERROR, "Destination Address < 4 bytes ?!?\n"); rc = GSM411_RP_CAUSE_SEMANT_INC_MSG; goto out; } @@ -560,8 +555,7 @@ static int gsm340_rx_tpdu(struct gsm_trans *trans, struct msgb *msg, sms_vp = 0; break; default: - LOGP(DLSMS, LOGL_NOTICE, - "SMS Validity period not implemented: 0x%02x\n", sms_vpf); + LOG_TRANS(trans, LOGL_NOTICE, "SMS Validity period not implemented: 0x%02x\n", sms_vpf); rc = GSM411_RP_CAUSE_MO_NET_OUT_OF_ORDER; goto out; } @@ -583,21 +577,22 @@ static int gsm340_rx_tpdu(struct gsm_trans *trans, struct msgb *msg, OSMO_STRLCPY_ARRAY(gsms->src.addr, conn->vsub->msisdn); - LOGP(DLSMS, LOGL_INFO, "RX SMS: Sender: %s, MTI: 0x%02x, VPF: 0x%02x, " - "MR: 0x%02x PID: 0x%02x, DCS: 0x%02x, DA: %s, " - "UserDataLength: 0x%02x, UserData: \"%s\"\n", - vlr_subscr_name(conn->vsub), sms_mti, sms_vpf, gsms->msg_ref, - gsms->protocol_id, gsms->data_coding_scheme, gsms->dst.addr, - gsms->user_data_len, - sms_alphabet == DCS_7BIT_DEFAULT ? gsms->text : - osmo_hexdump(gsms->user_data, gsms->user_data_len)); + LOG_TRANS(trans, LOGL_INFO, + "MO SMS -- MTI: 0x%02x, VPF: 0x%02x, " + "MR: 0x%02x PID: 0x%02x, DCS: 0x%02x, DA: %s, " + "UserDataLength: 0x%02x, UserData: \"%s\"\n", + sms_mti, sms_vpf, gsms->msg_ref, + gsms->protocol_id, gsms->data_coding_scheme, gsms->dst.addr, + gsms->user_data_len, + sms_alphabet == DCS_7BIT_DEFAULT ? gsms->text : + osmo_hexdump(gsms->user_data, gsms->user_data_len)); gsms->validity_minutes = gsm340_validity_period(sms_vpf, sms_vp); /* FIXME: This looks very wrong */ send_signal(0, NULL, gsms, 0); - rc = sms_route_mt_sms(conn, gsms); + rc = sms_route_mt_sms(trans, gsms); /* * This SMS got routed through SMPP or no receiver exists. @@ -607,15 +602,15 @@ static int gsm340_rx_tpdu(struct gsm_trans *trans, struct msgb *msg, switch (sms_mti) { case GSM340_SMS_SUBMIT_MS2SC: /* MS is submitting a SMS */ - rc = gsm340_rx_sms_submit(gsms); + rc = gsm340_rx_sms_submit(trans, gsms); break; case GSM340_SMS_COMMAND_MS2SC: case GSM340_SMS_DELIVER_REP_MS2SC: - LOGP(DLSMS, LOGL_NOTICE, "Unimplemented MTI 0x%02x\n", sms_mti); + LOG_TRANS(trans, LOGL_NOTICE, "Unimplemented MTI 0x%02x\n", sms_mti); rc = GSM411_RP_CAUSE_IE_NOTEXIST; break; default: - LOGP(DLSMS, LOGL_NOTICE, "Undefined MTI 0x%02x\n", sms_mti); + LOG_TRANS(trans, LOGL_NOTICE, "Undefined MTI 0x%02x\n", sms_mti); rc = GSM411_RP_CAUSE_IE_NOTEXIST; break; } @@ -646,7 +641,7 @@ int gsm411_send_rp_ack(struct gsm_trans *trans, uint8_t msg_ref) { struct msgb *msg = gsm411_msgb_alloc(); - DEBUGP(DLSMS, "TX: SMS RP ACK\n"); + LOG_TRANS(trans, LOGL_DEBUG, "TX: SMS RP ACK\n"); return gsm411_rp_sendmsg(&trans->sms.smr_inst, msg, GSM411_MT_RP_ACK_MT, msg_ref, GSM411_SM_RL_REPORT_REQ); @@ -659,7 +654,7 @@ int gsm411_send_rp_error(struct gsm_trans *trans, uint8_t msg_ref, msgb_tv_put(msg, 1, cause); - LOGP(DLSMS, LOGL_NOTICE, "TX: SMS RP ERROR, cause %d (%s)\n", cause, + LOG_TRANS(trans, LOGL_NOTICE, "TX: SMS RP ERROR, cause %d (%s)\n", cause, get_value_string(gsm411_rp_cause_strs, cause)); return gsm411_rp_sendmsg(&trans->sms.smr_inst, msg, @@ -711,14 +706,14 @@ static int gsm411_rx_rp_data(struct msgb *msg, struct gsm_trans *trans, if (rpud_len) rp_ud = &rph->data[1+src_len+1+dst_len+1]; - DEBUGP(DLSMS, "RX_RP-DATA: src_len=%u, dst_len=%u ud_len=%u\n", + LOG_TRANS(trans, LOGL_DEBUG, "RX_RP-DATA: src_len=%u, dst_len=%u ud_len=%u\n", src_len, dst_len, rpud_len); if (src_len && src) - LOGP(DLSMS, LOGL_ERROR, "RP-DATA (MO) with SRC ?!?\n"); + LOG_TRANS(trans, LOGL_ERROR, "RP-DATA (MO) with SRC ?!?\n"); if (!dst_len || !dst || !rpud_len || !rp_ud) { - LOGP(DLSMS, LOGL_ERROR, + LOG_TRANS(trans, LOGL_ERROR, "RP-DATA (MO) without DST or TPDU ?!?\n"); gsm411_send_rp_error(trans, rph->msg_ref, GSM411_RP_CAUSE_INV_MAND_INF); @@ -727,12 +722,12 @@ static int gsm411_rx_rp_data(struct msgb *msg, struct gsm_trans *trans, msg->l4h = rp_ud; - DEBUGP(DLSMS, "DST(%u,%s)\n", dst_len, osmo_hexdump(dst, dst_len)); + LOG_TRANS(trans, LOGL_DEBUG, "DST(%u,%s)\n", dst_len, osmo_hexdump(dst, dst_len)); return gsm411_rx_rp_ud(msg, trans, rph, dst, dst_len); } -static struct gsm_sms *sms_report_alloc(struct gsm_sms *sms) +static struct gsm_sms *sms_report_alloc(struct gsm_sms *sms, struct gsm_trans *trans) { struct gsm_sms *sms_report; int len; @@ -757,7 +752,7 @@ static struct gsm_sms *sms_report_alloc(struct gsm_sms *sms) "id:%.08llu sub:000 dlvrd:000 submit date:YYMMDDhhmm done date:YYMMDDhhmm stat:DELIVRD err:000 text:%.20s", sms->id, sms->text); sms_report->user_data_len = len; - LOGP(DLSMS, LOGL_NOTICE, "%s\n", sms_report->user_data); + LOG_TRANS(trans, LOGL_NOTICE, "%s\n", sms_report->user_data); /* This represents a sms report. */ sms_report->is_report = true; @@ -765,25 +760,24 @@ static struct gsm_sms *sms_report_alloc(struct gsm_sms *sms) return sms_report; } -static void sms_status_report(struct gsm_sms *gsms, - struct ran_conn *conn) +static void sms_status_report(struct gsm_sms *gsms, struct gsm_trans *trans) { struct gsm_sms *sms_report; int rc; - sms_report = sms_report_alloc(gsms); + sms_report = sms_report_alloc(gsms, trans); - rc = sms_route_mt_sms(conn, sms_report); + rc = sms_route_mt_sms(trans, sms_report); if (rc < 0) { - LOGP(DLSMS, LOGL_ERROR, - "Failed to send status report! err=%d\n", rc); + LOG_TRANS(trans, LOGL_ERROR, "Failed to send status report! err=%d\n", rc); + return; } /* No route via SMPP, send the GSM 03.40 status-report now. */ if (sms_report->receiver) - gsm340_rx_sms_submit(sms_report); + gsm340_rx_sms_submit(trans, sms_report); - LOGP(DLSMS, LOGL_NOTICE, "Status report has been sent\n"); + LOG_TRANS(trans, LOGL_NOTICE, "Status report has been sent\n"); sms_free(sms_report); } @@ -804,7 +798,7 @@ static int gsm411_rx_rp_ack(struct gsm_trans *trans, } if (!sms) { - LOGP(DLSMS, LOGL_ERROR, "RX RP-ACK but no sms in transaction?!?\n"); + LOG_TRANS(trans, LOGL_ERROR, "RX RP-ACK but no sms in transaction?!?\n"); return gsm411_send_rp_error(trans, rph->msg_ref, GSM411_RP_CAUSE_PROTOCOL_ERR); } @@ -815,7 +809,7 @@ static int gsm411_rx_rp_ack(struct gsm_trans *trans, send_signal(S_SMS_DELIVERED, trans, sms, 0); if (sms->status_rep_req) - sms_status_report(sms, trans->conn); + sms_status_report(sms, trans); sms_free(sms); trans->sms.sms = NULL; @@ -835,9 +829,8 @@ static int gsm411_rx_rp_error(struct gsm_trans *trans, * successfully receive the SMS. We need to investigate * the cause and take action depending on it */ - LOGP(DLSMS, LOGL_NOTICE, "%s: RX SMS RP-ERROR, cause %d:%d (%s)\n", - vlr_subscr_name(trans->conn->vsub), cause_len, cause, - get_value_string(gsm411_rp_cause_strs, cause)); + LOG_TRANS(trans, LOGL_NOTICE, "RX SMS RP-ERROR, cause %d:%d (%s)\n", + cause_len, cause, get_value_string(gsm411_rp_cause_strs, cause)); if (trans->net->sms_over_gsup) { /* Forward towards SMSC via GSUP */ @@ -845,8 +838,7 @@ static int gsm411_rx_rp_error(struct gsm_trans *trans, } if (!sms) { - LOGP(DLSMS, LOGL_ERROR, - "RX RP-ERR, but no sms in transaction?!?\n"); + LOG_TRANS(trans, LOGL_ERROR, "RX RP-ERR, but no sms in transaction?!?\n"); return -EINVAL; #if 0 return gsm411_send_rp_error(trans, rph->msg_ref, @@ -905,15 +897,15 @@ static int gsm411_rx_rl_data(struct msgb *msg, struct gsm48_hdr *gh, switch (msg_type) { case GSM411_MT_RP_DATA_MO: - DEBUGP(DLSMS, "RX SMS RP-DATA (MO)\n"); + LOG_TRANS(trans, LOGL_DEBUG, "RX SMS RP-DATA (MO)\n"); rc = gsm411_rx_rp_data(msg, trans, rp_data); break; case GSM411_MT_RP_SMMA_MO: - DEBUGP(DLSMS, "RX SMS RP-SMMA\n"); + LOG_TRANS(trans, LOGL_DEBUG, "RX SMS RP-SMMA\n"); rc = gsm411_rx_rp_smma(msg, trans, rp_data); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Invalid RP type 0x%02x\n", msg_type); + LOG_TRANS(trans, LOGL_NOTICE, "Invalid RP type 0x%02x\n", msg_type); rc = -EINVAL; break; } @@ -931,15 +923,15 @@ static int gsm411_rx_rl_report(struct msgb *msg, struct gsm48_hdr *gh, switch (msg_type) { case GSM411_MT_RP_ACK_MO: - DEBUGP(DLSMS, "RX SMS RP-ACK (MO)\n"); + LOG_TRANS(trans, LOGL_DEBUG, "RX SMS RP-ACK (MO)\n"); rc = gsm411_rx_rp_ack(trans, rp_data); break; case GSM411_MT_RP_ERROR_MO: - DEBUGP(DLSMS, "RX SMS RP-ERROR (MO)\n"); + LOG_TRANS(trans, LOGL_DEBUG, "RX SMS RP-ERROR (MO)\n"); rc = gsm411_rx_rp_error(trans, rp_data); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Invalid RP type 0x%02x\n", msg_type); + LOG_TRANS(trans, LOGL_NOTICE, "Invalid RP type 0x%02x\n", msg_type); rc = -EINVAL; break; } @@ -967,7 +959,7 @@ int gsm411_rl_recv(struct gsm411_smr_inst *inst, int msg_type, rc = gsm411_rx_rl_report(msg, gh, trans); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Unhandled SM-RL message 0x%x\n", msg_type); + LOG_TRANS(trans, LOGL_NOTICE, "Unhandled SM-RL message 0x%x\n", msg_type); rc = -EINVAL; } @@ -988,21 +980,21 @@ static int gsm411_mn_recv(struct gsm411_smc_inst *inst, int msg_type, switch (msg_type) { case GSM411_MNSMS_EST_IND: case GSM411_MNSMS_DATA_IND: - DEBUGP(DLSMS, "MNSMS-DATA/EST-IND\n"); + LOG_TRANS(trans, LOGL_DEBUG, "MNSMS-DATA/EST-IND\n"); rc = gsm411_smr_recv(&trans->sms.smr_inst, msg_type, msg); break; case GSM411_MNSMS_ERROR_IND: if (gh) - DEBUGP(DLSMS, "MNSMS-ERROR-IND, cause %d (%s)\n", + LOG_TRANS(trans, LOGL_DEBUG, "MNSMS-ERROR-IND, cause %d (%s)\n", gh->data[0], get_value_string(gsm411_cp_cause_strs, gh->data[0])); else - DEBUGP(DLSMS, "MNSMS-ERROR-IND, no cause\n"); + LOG_TRANS(trans, LOGL_DEBUG, "MNSMS-ERROR-IND, no cause\n"); rc = gsm411_smr_recv(&trans->sms.smr_inst, msg_type, msg); break; default: - LOGP(DLSMS, LOGL_NOTICE, "Unhandled MNCCSMS msg 0x%x\n", msg_type); + LOG_TRANS(trans, LOGL_NOTICE, "Unhandled MNCCSMS msg 0x%x\n", msg_type); rc = -EINVAL; } @@ -1015,7 +1007,7 @@ static struct gsm_trans *gsm411_trans_init(struct gsm_network *net, struct vlr_s /* Allocate a new transaction */ struct gsm_trans *trans = trans_alloc(net, vsub, GSM48_PDISC_SMS, tid, new_callref++); if (!trans) { - LOGP(DLSMS, LOGL_ERROR, "No memory for transaction\n"); + LOG_TRANS(trans, LOGL_ERROR, "No memory for transaction\n"); return NULL; } @@ -1058,15 +1050,13 @@ static struct gsm_trans *gsm411_alloc_mt_trans(struct gsm_network *net, struct vlr_subscr *vsub) { struct ran_conn *conn; - struct gsm_trans *trans; + struct gsm_trans *trans = NULL; int tid; - LOGP(DLSMS, LOGL_INFO, "Going to send a MT SMS\n"); - /* Generate a new transaction ID */ tid = trans_assign_trans_id(net, vsub, GSM48_PDISC_SMS); if (tid == -1) { - LOGP(DLSMS, LOGL_ERROR, "No available transaction IDs\n"); + LOG_TRANS(trans, LOGL_ERROR, "No available transaction IDs\n"); return NULL; } @@ -1078,9 +1068,11 @@ static struct gsm_trans *gsm411_alloc_mt_trans(struct gsm_network *net, if (!trans) return NULL; + LOG_TRANS(trans, LOGL_INFO, "Going to send a MT SMS\n"); + /* Assign a unique SM-RP Message Reference */ if (gsm411_assign_sm_rp_mr(trans) != 0) { - LOGP(DLSMS, LOGL_ERROR, "Failed to assign SM-RP-MR\n"); + LOG_TRANS(trans, LOGL_ERROR, "Failed to assign SM-RP-MR\n"); trans_free(trans); return NULL; } @@ -1138,10 +1130,10 @@ int gsm411_send_sms(struct gsm_network *net, if (sms->is_report) { /* generate the 03.40 SMS-STATUS-REPORT TPDU */ - rc = gsm340_gen_sms_status_report_tpdu(msg, sms); + rc = gsm340_gen_sms_status_report_tpdu(trans, msg, sms); } else { /* generate the 03.40 SMS-DELIVER TPDU */ - rc = gsm340_gen_sms_deliver_tpdu(msg, sms); + rc = gsm340_gen_sms_deliver_tpdu(trans, msg, sms); } if (rc < 0) { send_signal(S_SMS_UNKNOWN_ERROR, trans, sms, 0); @@ -1216,16 +1208,13 @@ int gsm0411_rcv_sms(struct ran_conn *conn, return -EIO; /* FIXME: send some error message */ - DEBUGP(DLSMS, "receiving data (trans_id=%x, msg_type=%s)\n", transaction_id, - gsm48_pdisc_msgtype_name(gsm48_hdr_pdisc(gh), gsm48_hdr_msg_type(gh))); - trans = trans_find_by_id(conn, GSM48_PDISC_SMS, transaction_id); /* * A transaction we created but don't know about? */ if (!trans && (transaction_id & 0x8) == 0) { - LOGP(DLSMS, LOGL_ERROR, "trans_id=%x allocated by us but known " + LOG_TRANS(trans, LOGL_ERROR, "trans_id=%x allocated by us but known " "to us anymore. We are ignoring it, maybe a CP-ERROR " "from a MS?\n", transaction_id); @@ -1246,6 +1235,9 @@ int gsm0411_rcv_sms(struct ran_conn *conn, cm_service_request_concludes(conn, msg); } + LOG_TRANS(trans, LOGL_DEBUG, "receiving SMS message %s\n", + gsm48_pdisc_msgtype_name(gsm48_hdr_pdisc(gh), gsm48_hdr_msg_type(gh))); + /* 5.4: For MO, if a CP-DATA is received for a new * transaction, equals reception of an implicit * last CP-ACK for previous transaction */ @@ -1263,7 +1255,7 @@ int gsm0411_rcv_sms(struct ran_conn *conn, if (!ptrans) continue; - DEBUGP(DLSMS, "Implicit CP-ACK for trans_id=%x\n", i); + LOG_TRANS(ptrans, LOGL_DEBUG, "Implicit CP-ACK for trans_id=%x\n", i); /* Finish it for good */ trans_free(ptrans); @@ -1291,7 +1283,7 @@ void _gsm411_sms_trans_free(struct gsm_trans *trans) trans->sms.smc_inst.mm_send = NULL; if (trans->sms.sms) { - LOGP(DLSMS, LOGL_ERROR, "Transaction contains SMS.\n"); + LOG_TRANS(trans, LOGL_ERROR, "Freeing transaction that still contains an SMS -- discarding\n"); send_signal(S_SMS_UNKNOWN_ERROR, trans, trans->sms.sms, 0); sms_free(trans->sms.sms); trans->sms.sms = NULL; @@ -1316,7 +1308,7 @@ void gsm411_sapi_n_reject(struct ran_conn *conn) sms = trans->sms.sms; if (!sms) { - LOGP(DLSMS, LOGL_ERROR, "SAPI Reject but no SMS.\n"); + LOG_TRANS(trans, LOGL_ERROR, "SAPI Reject but no SMS.\n"); continue; } diff --git a/src/libmsc/gsm_04_11_gsup.c b/src/libmsc/gsm_04_11_gsup.c index eb092ae0b..cd83b4102 100644 --- a/src/libmsc/gsm_04_11_gsup.c +++ b/src/libmsc/gsm_04_11_gsup.c @@ -58,7 +58,7 @@ int gsm411_gsup_mo_fwd_sm_req(struct gsm_trans *trans, struct msgb *msg, /* Associate logging messages with this subscriber */ log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); - LOGP(DLSMS, LOGL_DEBUG, "TX GSUP MO-forwardSM-Req\n"); + LOG_TRANS(trans, LOGL_DEBUG, "TX GSUP MO-forwardSM-Req\n"); /* Assign SM-RP-MR to transaction state */ trans->sms.sm_rp_mr = sm_rp_mr; @@ -67,7 +67,7 @@ int gsm411_gsup_mo_fwd_sm_req(struct gsm_trans *trans, struct msgb *msg, bcd_len = gsm48_encode_bcd_number(bcd_buf, sizeof(bcd_buf), 0, trans->vsub->msisdn); if (bcd_len <= 0 || bcd_len > sizeof(bcd_buf)) { - LOGP(DLSMS, LOGL_ERROR, "Failed to encode subscriber's MSISDN\n"); + LOG_TRANS(trans, LOGL_ERROR, "Failed to encode subscriber's MSISDN\n"); return -EINVAL; } @@ -99,7 +99,7 @@ int gsm411_gsup_mo_ready_for_sm_req(struct gsm_trans *trans, uint8_t sm_rp_mr) /* Associate logging messages with this subscriber */ log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); - LOGP(DLSMS, LOGL_DEBUG, "TX GSUP READY-FOR-SM Req\n"); + LOG_TRANS(trans, LOGL_DEBUG, "TX GSUP READY-FOR-SM Req\n"); /* Assign SM-RP-MR to transaction state */ trans->sms.sm_rp_mr = sm_rp_mr; @@ -147,9 +147,6 @@ int gsm411_gsup_mo_handler(struct vlr_subscr *vsub, OSMO_ASSERT(0); } - LOGP(DLSMS, LOGL_DEBUG, "RX %s-%s\n", msg_name, - msg_is_err ? "Err" : "Res"); - /* Make sure that 'SMS over GSUP' is expected */ if (!net->sms_over_gsup) { /* TODO: notify sender about that? */ @@ -173,6 +170,8 @@ int gsm411_gsup_mo_handler(struct vlr_subscr *vsub, return -EIO; /* TODO: notify sender about that? */ } + LOG_TRANS(trans, LOGL_DEBUG, "RX %s-%s\n", msg_name, msg_is_err ? "Err" : "Res"); + /* Send either RP-ERROR, or RP-ACK */ if (msg_is_err) { /* TODO: handle optional SM-RP-UI payload (requires API change) */ @@ -198,7 +197,7 @@ int gsm411_gsup_mt_fwd_sm_res(struct gsm_trans *trans, uint8_t sm_rp_mr) /* Associate logging messages with this subscriber */ log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); - LOGP(DLSMS, LOGL_DEBUG, "TX MT-forwardSM-Res\n"); + LOG_TRANS(trans, LOGL_DEBUG, "TX MT-forwardSM-Res\n"); /* Initialize a new GSUP message */ gsup_sm_msg_init(&gsup_msg, OSMO_GSUP_MSGT_MT_FORWARD_SM_RESULT, @@ -215,7 +214,7 @@ int gsm411_gsup_mt_fwd_sm_err(struct gsm_trans *trans, /* Associate logging messages with this subscriber */ log_set_context(LOG_CTX_VLR_SUBSCR, trans->vsub); - LOGP(DLSMS, LOGL_DEBUG, "TX MT-forwardSM-Err\n"); + LOG_TRANS(trans, LOGL_DEBUG, "TX MT-forwardSM-Err\n"); /* Initialize a new GSUP message */ gsup_sm_msg_init(&gsup_msg, OSMO_GSUP_MSGT_MT_FORWARD_SM_ERROR, diff --git a/src/libmsc/gsm_09_11.c b/src/libmsc/gsm_09_11.c index c133656dd..25fe4aa83 100644 --- a/src/libmsc/gsm_09_11.c +++ b/src/libmsc/gsm_09_11.c @@ -60,8 +60,7 @@ static void ncss_session_timeout_handler(void *_trans) if (trans->net->ncss_guard_timeout == 0) return; - LOGP(DMM, LOGL_NOTICE, "SS/USSD session timeout, releasing " - "transaction (trans=%p, callref=%x)\n", trans, trans->callref); + LOG_TRANS(trans, LOGL_NOTICE, "SS/USSD session timeout, releasing\n"); /* Indicate connection release to subscriber (if active) */ if (trans->conn != NULL) { @@ -103,9 +102,6 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) /* Associate logging messages with this subscriber */ log_set_context(LOG_CTX_VLR_SUBSCR, conn->vsub); - DEBUGP(DMM, "Received SS/USSD data (trans_id=%x, msg_type=%s)\n", - tid, gsm48_pdisc_msgtype_name(GSM48_PDISC_NC_SS, msg_type)); - /* Reuse existing transaction, or create a new one */ trans = trans_find_by_id(conn, GSM48_PDISC_NC_SS, tid); if (!trans) { @@ -121,20 +117,18 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) * a supplementary service. */ if (msg_type != GSM0480_MTYPE_REGISTER) { - LOGP(DMM, LOGL_ERROR, "Unexpected message (msg_type=%s), " - "transaction is not allocated yet\n", - gsm48_pdisc_msgtype_name(GSM48_PDISC_NC_SS, msg_type)); + LOG_TRANS(trans, LOGL_ERROR, "Rx wrong SS/USSD message type for new transaction: %s\n", + gsm48_pdisc_msgtype_name(GSM48_PDISC_NC_SS, msg_type)); gsm48_tx_simple(conn, GSM48_PDISC_NC_SS | (tid << 4), GSM0480_MTYPE_RELEASE_COMPLETE); return -EINVAL; } - DEBUGP(DMM, " -> (new transaction)\n"); trans = trans_alloc(conn->network, conn->vsub, GSM48_PDISC_NC_SS, tid, new_callref++); if (!trans) { - LOGP(DMM, LOGL_ERROR, " -> No memory for trans\n"); + LOG_TRANS(trans, LOGL_ERROR, " -> No memory for trans\n"); gsm48_tx_simple(conn, GSM48_PDISC_NC_SS | (tid << 4), GSM0480_MTYPE_RELEASE_COMPLETE); @@ -153,6 +147,9 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) cm_service_request_concludes(conn, msg); } + LOG_TRANS(trans, LOGL_DEBUG, "Received SS/USSD msg %s\n", + gsm48_pdisc_msgtype_name(GSM48_PDISC_NC_SS, msg_type)); + /* (Re)schedule the inactivity timer */ if (conn->network->ncss_guard_timeout > 0) { osmo_timer_schedule(&trans->ss.timer_guard, @@ -163,16 +160,15 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) rc = gsm0480_extract_ie_by_tag(gh, msgb_l3len(msg), &facility_ie, &facility_ie_len, GSM0480_IE_FACILITY); if (rc) { - LOGP(DMM, LOGL_ERROR, "GSM 04.80 message parsing error, " - "couldn't extract Facility IE\n"); + LOG_TRANS(trans, LOGL_ERROR, "GSM 04.80 message parsing error, couldn't extract Facility IE\n"); goto error; } /* Facility IE is optional for RELEASE COMPLETE */ if (msg_type != GSM0480_MTYPE_RELEASE_COMPLETE) { if (!facility_ie || facility_ie_len < 2) { - LOGP(DMM, LOGL_ERROR, "GSM 04.80 message parsing error, " - "missing mandatory Facility IE\n"); + LOG_TRANS(trans, LOGL_ERROR, "GSM 04.80 message parsing error," + " missing mandatory Facility IE\n"); rc = -EINVAL; goto error; } @@ -211,7 +207,7 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) /* Allocate GSUP message buffer */ gsup_msgb = osmo_gsup_client_msgb_alloc(); if (!gsup_msgb) { - LOGP(DMM, LOGL_ERROR, "Couldn't allocate GSUP message\n"); + LOG_TRANS(trans, LOGL_ERROR, "Couldn't allocate GSUP message\n"); rc = -ENOMEM; goto error; } @@ -219,14 +215,14 @@ int gsm0911_rcv_nc_ss(struct ran_conn *conn, struct msgb *msg) /* Encode GSUP message */ rc = osmo_gsup_encode(gsup_msgb, &gsup_msg); if (rc) { - LOGP(DMM, LOGL_ERROR, "Couldn't encode GSUP message\n"); + LOG_TRANS(trans, LOGL_ERROR, "Couldn't encode GSUP message\n"); goto error; } /* Finally send */ rc = osmo_gsup_client_send(conn->network->vlr->gsup_client, gsup_msgb); if (rc) { - LOGP(DMM, LOGL_ERROR, "Couldn't send GSUP message\n"); + LOG_TRANS(trans, LOGL_ERROR, "Couldn't send GSUP message\n"); goto error; } @@ -323,33 +319,37 @@ static struct gsm_trans *establish_nc_ss_trans(struct gsm_network *net, struct gsm_trans *trans, *transt; int tid; + /* Allocate transaction first, for log context */ + trans = trans_alloc(net, vsub, GSM48_PDISC_NC_SS, + TRANS_ID_UNASSIGNED, gsup_msg->session_id); + + if (!trans) { + LOG_TRANS(trans, LOGL_ERROR, " -> No memory for trans\n"); + return NULL; + } + if (gsup_msg->session_state != OSMO_GSUP_SESSION_STATE_BEGIN) { - LOGP(DMM, LOGL_ERROR, "Received non-BEGIN message " + LOG_TRANS(trans, LOGL_ERROR, "Received non-BEGIN message " "for non-existing transaction\n"); + trans_free(trans); return NULL; } if (!gsup_msg->ss_info || gsup_msg->ss_info_len < 2) { - LOGP(DMM, LOGL_ERROR, "Missing mandatory Facility IE\n"); + LOG_TRANS(trans, LOGL_ERROR, "Missing mandatory Facility IE\n"); + trans_free(trans); return NULL; } /* If subscriber is not "attached" */ if (!vsub->cgi.lai.lac) { - LOGP(DMM, LOGL_ERROR, "Network-originated session " + LOG_TRANS(trans, LOGL_ERROR, "Network-originated session " "rejected - subscriber is not attached\n"); + trans_free(trans); return NULL; } - DEBUGP(DMM, "Establishing network-originated session\n"); - - /* Allocate a new transaction */ - trans = trans_alloc(net, vsub, GSM48_PDISC_NC_SS, - TRANS_ID_UNASSIGNED, gsup_msg->session_id); - if (!trans) { - LOGP(DMM, LOGL_ERROR, " -> No memory for trans\n"); - return NULL; - } + LOG_TRANS(trans, LOGL_DEBUG, "Establishing network-originated session\n"); /* Count active NC SS/USSD sessions */ osmo_counter_inc(net->active_nc_ss); @@ -357,7 +357,7 @@ static struct gsm_trans *establish_nc_ss_trans(struct gsm_network *net, /* Assign transaction ID */ tid = trans_assign_trans_id(trans->net, trans->vsub, GSM48_PDISC_NC_SS); if (tid < 0) { - LOGP(DMM, LOGL_ERROR, "No free transaction ID\n"); + LOG_TRANS(trans, LOGL_ERROR, "No free transaction ID\n"); /* TODO: inform HLR about this */ /* TODO: release connection with subscriber */ trans->callref = 0; @@ -379,7 +379,7 @@ static struct gsm_trans *establish_nc_ss_trans(struct gsm_network *net, return trans; } - DEBUGP(DMM, "Triggering Paging Request\n"); + LOG_TRANS(trans, LOGL_DEBUG, "Triggering Paging Request\n"); /* Find transaction with this subscriber already paging */ llist_for_each_entry(transt, &net->trans_list, entry) { @@ -387,7 +387,7 @@ static struct gsm_trans *establish_nc_ss_trans(struct gsm_network *net, if (transt == trans || transt->vsub != vsub) continue; - LOGP(DMM, LOGL_ERROR, "Paging already started, " + LOG_TRANS(trans, LOGL_ERROR, "Paging already started, " "rejecting message...\n"); trans_free(trans); return NULL; @@ -398,7 +398,7 @@ static struct gsm_trans *establish_nc_ss_trans(struct gsm_network *net, &handle_paging_event, trans, "GSM 09.11 SS/USSD", SGSAP_SERV_IND_CS_CALL); if (!trans->paging_request) { - LOGP(DMM, LOGL_ERROR, "Failed to allocate paging token\n"); + LOG_TRANS(trans, LOGL_ERROR, "Failed to allocate paging token\n"); trans_free(trans); return NULL; } @@ -510,7 +510,7 @@ int gsm0911_gsup_handler(struct vlr_subscr *vsub, /* Missing or incorrect session state */ case OSMO_GSUP_SESSION_STATE_NONE: default: - LOGP(DMM, LOGL_ERROR, "Unexpected session state %d\n", + LOG_TRANS(trans, LOGL_ERROR, "Unexpected session state %d\n", gsup_msg->session_state); /* FIXME: send ERROR back to the HLR */ msgb_free(ss_msg); @@ -520,7 +520,7 @@ int gsm0911_gsup_handler(struct vlr_subscr *vsub, /* Facility IE is optional only for RELEASE COMPLETE */ if (gh->msg_type != GSM0480_MTYPE_RELEASE_COMPLETE) { if (!gsup_msg->ss_info || gsup_msg->ss_info_len < 2) { - LOGP(DMM, LOGL_ERROR, "Missing mandatory Facility IE " + LOG_TRANS(trans, LOGL_ERROR, "Missing mandatory Facility IE " "for mapped 0x%02x message\n", gh->msg_type); /* FIXME: send ERROR back to the HLR */ msgb_free(ss_msg); diff --git a/src/libmsc/transaction.c b/src/libmsc/transaction.c index b38c15216..665ad46b2 100644 --- a/src/libmsc/transaction.c +++ b/src/libmsc/transaction.c @@ -110,18 +110,14 @@ struct gsm_trans *trans_alloc(struct gsm_network *net, uint8_t protocol, uint8_t trans_id, uint32_t callref) { - struct gsm_trans *trans; + struct gsm_trans *trans = NULL; /* (NULL for LOG_TRANS() before allocation) */ /* a valid subscriber is indispensable */ if (vsub == NULL) { - LOGP(DVLR, LOGL_ERROR, - "unable to alloc transaction, invalid subscriber (NULL)\n"); + LOG_TRANS(trans, LOGL_ERROR, "unable to alloc transaction, invalid subscriber (NULL)\n"); return NULL; } - DEBUGP(DCC, "(ti %02x sub %s callref %x) New transaction\n", - trans_id, vlr_subscr_name(vsub), callref); - trans = talloc_zero(tall_trans_ctx, struct gsm_trans); if (!trans) return NULL; @@ -135,6 +131,7 @@ struct gsm_trans *trans_alloc(struct gsm_network *net, trans->net = net; llist_add_tail(&trans->entry, &net->trans_list); + LOG_TRANS(trans, LOGL_DEBUG, "New transaction\n"); return trans; } @@ -146,6 +143,8 @@ void trans_free(struct gsm_trans *trans) enum ran_conn_use conn_usage_token; struct ran_conn *conn; + LOG_TRANS(trans, LOGL_DEBUG, "Freeing transaction\n"); + switch (trans->protocol) { case GSM48_PDISC_CC: _gsm48_cc_trans_free(trans); |