From 62977d048487837f73f4eb9dfcfeb0be194050b0 Mon Sep 17 00:00:00 2001 From: Max Date: Mon, 1 Aug 2022 22:50:52 +0700 Subject: [PATCH] Add ESME-specific logging Related: OS#5568 Change-Id: Ie5ddde762350385f8d18ee1d441584a41b0290ec --- include/osmocom/smpp/smpp.h | 6 +++ src/libsmpputil/smpp_msc.c | 4 +- src/libsmpputil/smpp_smsc.c | 93 ++++++++++++++----------------------- src/utils/smpp_mirror.c | 14 ++---- 4 files changed, 47 insertions(+), 70 deletions(-) diff --git a/include/osmocom/smpp/smpp.h b/include/osmocom/smpp/smpp.h index cc0e8003a..df5e163c0 100644 --- a/include/osmocom/smpp/smpp.h +++ b/include/osmocom/smpp/smpp.h @@ -11,6 +11,12 @@ enum esme_read_state { READ_ST_IN_MSG = 1, }; +#define LOGPESME(ESME, LEVEL, FMT, ARGS...) \ + LOGP(DSMPP, LEVEL, "[%s] " FMT, (ESME)->system_id, ##ARGS) + +#define LOGPESMERR(ESME, FMT, ARGS...) \ + LOGPESME(ESME, LOGL_ERROR, "Error (%s) " FMT, smpp34_strerror, ##ARGS) + /*! \brief Ugly wrapper. libsmpp34 should do this itself! */ #define SMPP34_UNPACK(rc, type, str, data, len) { \ memset(str, 0, sizeof(*str)); \ diff --git a/src/libsmpputil/smpp_msc.c b/src/libsmpputil/smpp_msc.c index 090905a13..cc618cd1b 100644 --- a/src/libsmpputil/smpp_msc.c +++ b/src/libsmpputil/smpp_msc.c @@ -341,9 +341,7 @@ static void alert_all_esme(struct smsc *smsc, struct vlr_subscr *vsub, continue; } if (esme->acl && !esme->acl->alert_notifications) { - LOGP(DSMPP, LOGL_DEBUG, - "[%s] is not set to receive Alert Notifications\n", - esme->system_id); + LOGPESME(esme, LOGL_DEBUG, "is not set to receive Alert Notifications\n"); continue; } if (esme->acl && esme->acl->deliver_src_imsi) { diff --git a/src/libsmpputil/smpp_smsc.c b/src/libsmpputil/smpp_smsc.c index b03f7bea3..4cc76f54a 100644 --- a/src/libsmpputil/smpp_smsc.c +++ b/src/libsmpputil/smpp_smsc.c @@ -315,9 +315,7 @@ int smpp_route(const struct smsc *smsc, const struct osmo_smpp_addr *dest, struc *pesme = esme; return 0; } else - LOGP(DSMPP, LOGL_NOTICE, "[%s] is matching route, " - "but not bound for Rx, discarding MO SMS\n", - esme->system_id); + LOGPESME(esme, LOGL_NOTICE, "is matching route, but not bound for Rx, discarding MO SMS\n"); } *pesme = NULL; @@ -344,16 +342,14 @@ static int pack_and_send(struct osmo_esme *esme, uint32_t type, void *ptr) rc = smpp34_pack(type, msg->tail, msgb_tailroom(msg), &rlen, ptr); if (rc != 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error during smpp34_pack(): %s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "during smpp34_pack()\n"); msgb_free(msg); return -EINVAL; } msgb_put(msg, rlen); if (osmo_wqueue_enqueue(&esme->wqueue, msg) != 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Write queue full. Dropping message\n", - esme->system_id); + LOGPESME(esme, LOGL_ERROR, "Write queue full. Dropping message\n"); msgb_free(msg); return -EAGAIN; } @@ -371,8 +367,7 @@ static int smpp_tx_gen_nack(struct osmo_esme *esme, uint32_t seq, uint32_t statu nack.sequence_number = seq; nack.command_status = status; - LOGP(DSMPP, LOGL_ERROR, "[%s] Tx GENERIC NACK: %s\n", - esme->system_id, str_command_status(status, buf)); + LOGPESME(esme, LOGL_ERROR, "Tx GENERIC NACK: %s\n", str_command_status(status, buf)); return PACK_AND_SEND(esme, &nack); } @@ -394,13 +389,11 @@ static int smpp_handle_gen_nack(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, GENERIC_NACK, &nack, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } - LOGP(DSMPP, LOGL_ERROR, "[%s] Rx GENERIC NACK: %s\n", - esme->system_id, str_command_status(nack.command_status, buf)); + LOGPESME(esme, LOGL_ERROR, "Rx GENERIC NACK: %s\n", str_command_status(nack.command_status, buf)); return 0; } @@ -453,8 +446,7 @@ static int smpp_handle_bind_rx(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, BIND_RECEIVER, &bind, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } @@ -481,8 +473,7 @@ static int smpp_handle_bind_tx(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, BIND_TRANSMITTER, &bind, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } @@ -519,8 +510,7 @@ static int smpp_handle_bind_trx(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, BIND_TRANSCEIVER, &bind, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } @@ -546,14 +536,13 @@ static int smpp_handle_unbind(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, UNBIND, &unbind, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } INIT_RESP(UNBIND_RESP, &unbind_r, &unbind); - LOGP(DSMPP, LOGL_INFO, "[%s] Rx UNBIND\n", esme->system_id); + LOGPESME(esme, LOGL_INFO, "Rx UNBIND\n"); if (esme->bind_flags == 0) { unbind_r.command_status = ESME_RINVBNDSTS; @@ -575,16 +564,15 @@ static int smpp_handle_enq_link(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, ENQUIRE_LINK, &enq, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } - LOGP(DSMPP, LOGL_DEBUG, "[%s] Rx Enquire Link\n", esme->system_id); + LOGPESME(esme, LOGL_DEBUG, "Rx Enquire Link\n"); INIT_RESP(ENQUIRE_LINK_RESP, &enq_r, &enq); - LOGP(DSMPP, LOGL_DEBUG, "[%s] Tx Enquire Link Response\n", esme->system_id); + LOGPESME(esme, LOGL_DEBUG, "Tx Enquire Link Response\n"); return PACK_AND_SEND(esme, &enq_r); } @@ -634,10 +622,10 @@ int smpp_tx_alert(struct osmo_esme *esme, uint8_t ton, uint8_t npi, tlv.value.val08 = avail_status; build_tlv(&alert.tlv, &tlv); - LOGP(DSMPP, LOGL_DEBUG, "[%s] Tx ALERT_NOTIFICATION (%s/%u/%u): %s\n", - esme->system_id, alert.source_addr, alert.source_addr_ton, - alert.source_addr_npi, - get_value_string(smpp_avail_strs, avail_status)); + LOGPESME(esme, LOGL_DEBUG, "Tx ALERT_NOTIFICATION (%s/%u/%u): %s\n", + alert.source_addr, alert.source_addr_ton, + alert.source_addr_npi, + get_value_string(smpp_avail_strs, avail_status)); rc = PACK_AND_SEND(esme, &alert); destroy_tlv(alert.tlv); @@ -649,8 +637,7 @@ int smpp_tx_deliver(struct osmo_esme *esme, struct deliver_sm_t *deliver) { deliver->sequence_number = esme_inc_seq_nr(esme); - LOGP(DSMPP, LOGL_DEBUG, "[%s] Tx DELIVER-SM (from %s)\n", - esme->system_id, deliver->source_addr); + LOGPESME(esme, LOGL_DEBUG, "Tx DELIVER-SM (from %s)\n", deliver->source_addr); return PACK_AND_SEND(esme, deliver); } @@ -666,16 +653,14 @@ static int smpp_handle_deliver_resp(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, DELIVER_SM_RESP, &deliver_r, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } cmd = smpp_cmd_find_by_seqnum(esme, deliver_r.sequence_number); if (!cmd) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Rx DELIVER-SM RESP !? (%s)\n", - esme->system_id, get_value_string(smpp_status_strs, - deliver_r.command_status)); + LOGPESME(esme, LOGL_ERROR, "Rx DELIVER-SM RESP !? (%s)\n", + get_value_string(smpp_status_strs, deliver_r.command_status)); return -1; } @@ -684,9 +669,8 @@ static int smpp_handle_deliver_resp(struct osmo_esme *esme, struct msgb *msg) else smpp_cmd_err(cmd, deliver_r.command_status); - LOGP(DSMPP, LOGL_INFO, "[%s] Rx DELIVER-SM RESP (%s)\n", - esme->system_id, get_value_string(smpp_status_strs, - deliver_r.command_status)); + LOGPESME(esme, LOGL_INFO, "Rx DELIVER-SM RESP (%s)\n", + get_value_string(smpp_status_strs, deliver_r.command_status)); return 0; } @@ -702,8 +686,7 @@ static int smpp_handle_submit(struct osmo_esme *esme, struct msgb *msg) SMPP34_UNPACK(rc, SUBMIT_SM, &submit, msgb_data(msg), msgb_length(msg)); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error in smpp34_unpack():%s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "in smpp34_unpack()\n"); return rc; } @@ -714,9 +697,8 @@ static int smpp_handle_submit(struct osmo_esme *esme, struct msgb *msg) return PACK_AND_SEND(esme, &submit_r); } - LOGP(DSMPP, LOGL_INFO, "[%s] Rx SUBMIT-SM (%s/%u/%u)\n", - esme->system_id, submit.destination_addr, - submit.dest_addr_ton, submit.dest_addr_npi); + LOGPESME(esme, LOGL_INFO, "Rx SUBMIT-SM (%s/%u/%u)\n", + submit.destination_addr, submit.dest_addr_ton, submit.dest_addr_npi); INIT_RESP(SUBMIT_SM_RESP, &submit_r, &submit); @@ -733,8 +715,7 @@ static int smpp_pdu_rx(struct osmo_esme *esme, struct msgb *msg __uses) uint32_t cmd_id = smpp_msgb_cmdid(msg); int rc = 0; - LOGP(DSMPP, LOGL_DEBUG, "[%s] smpp_pdu_rx(%s)\n", esme->system_id, - msgb_hexdump(msg)); + LOGPESME(esme, LOGL_DEBUG, "smpp_pdu_rx(%s)\n", msgb_hexdump(msg)); switch (cmd_id) { case GENERIC_NACK: @@ -769,12 +750,10 @@ static int smpp_pdu_rx(struct osmo_esme *esme, struct msgb *msg __uses) case QUERY_SM: case REPLACE_SM: case SUBMIT_MULTI: - LOGP(DSMPP, LOGL_NOTICE, "[%s] Unimplemented PDU Command " - "0x%08x\n", esme->system_id, cmd_id); + LOGPESME(esme, LOGL_NOTICE, "Unimplemented PDU Command 0x%08x\n", cmd_id); break; default: - LOGP(DSMPP, LOGL_ERROR, "[%s] Unknown PDU Command 0x%08x\n", - esme->system_id, cmd_id); + LOGPESME(esme, LOGL_ERROR, "Unknown PDU Command 0x%08x\n", cmd_id); rc = smpp_tx_gen_nack(esme, smpp_msgb_seq(msg), ESME_RINVCMDID); break; } @@ -814,8 +793,7 @@ static int esme_link_read_cb(struct osmo_fd *ofd) rdlen = sizeof(uint32_t) - esme->read_idx; rc = read(ofd->fd, lenptr + esme->read_idx, rdlen); if (rc < 0) - LOGP(DSMPP, LOGL_ERROR, "[%s] read returned %zd (%s)\n", - esme->system_id, rc, strerror(errno)); + LOGPESME(esme, LOGL_ERROR, "read returned %zd (%s)\n", rc, strerror(errno)); OSMO_FD_CHECK_READ(rc, dead_socket); esme->read_idx += rc; @@ -823,8 +801,7 @@ static int esme_link_read_cb(struct osmo_fd *ofd) if (esme->read_idx >= sizeof(uint32_t)) { esme->read_len = ntohl(len); if (esme->read_len < 8 || esme->read_len > UINT16_MAX) { - LOGP(DSMPP, LOGL_ERROR, "[%s] length invalid %u\n", - esme->system_id, esme->read_len); + LOGPESME(esme, LOGL_ERROR, "length invalid %u\n", esme->read_len); goto dead_socket; } @@ -843,8 +820,8 @@ static int esme_link_read_cb(struct osmo_fd *ofd) rdlen = esme->read_len - esme->read_idx; rc = read(ofd->fd, msg->tail, OSMO_MIN(rdlen, msgb_tailroom(msg))); if (rc < 0) - LOGP(DSMPP, LOGL_ERROR, "[%s] read returned %zd (%s)\n", - esme->system_id, rc, strerror(errno)); + LOGPESME(esme, LOGL_ERROR, "read returned %zd (%s)\n", + rc, strerror(errno)); OSMO_FD_CHECK_READ(rc, dead_socket); esme->read_idx += rc; @@ -889,7 +866,7 @@ static int esme_link_write_cb(struct osmo_fd *ofd, struct msgb *msg) esme->acl->esme = NULL; smpp_esme_put(esme); } else if (rc < msgb_length(msg)) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Short write\n", esme->system_id); + LOGPESME(esme, LOGL_ERROR, "Short write\n"); return -1; } diff --git a/src/utils/smpp_mirror.c b/src/utils/smpp_mirror.c index 359389513..d6ac5cf4f 100644 --- a/src/utils/smpp_mirror.c +++ b/src/utils/smpp_mirror.c @@ -55,16 +55,14 @@ static int pack_and_send(struct esme *esme, uint32_t type, void *ptr) rc = smpp34_pack(type, msg->tail, msgb_tailroom(msg), &rlen, ptr); if (rc != 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Error during smpp34_pack(): %s\n", - esme->system_id, smpp34_strerror); + LOGPESMERR(esme, "during smpp34_pack()\n"); msgb_free(msg); return -EINVAL; } msgb_put(msg, rlen); if (osmo_wqueue_enqueue(&esme->wqueue, msg) != 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Write queue full. Dropping message\n", - esme->system_id); + LOGPESME(esme, LOGL_ERROR, "Write queue full. Dropping message\n"); msgb_free(msg); return -EAGAIN; } @@ -215,8 +213,7 @@ static int esme_read_cb(struct osmo_fd *ofd) rdlen = sizeof(uint32_t) - esme->read_idx; rc = read(ofd->fd, lenptr + esme->read_idx, rdlen); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] read returned %d\n", - esme->system_id, rc); + LOGPESME(esme, LOGL_ERROR, "read returned %d\n", rc); } else if (rc == 0) { goto dead_socket; } else @@ -242,8 +239,7 @@ static int esme_read_cb(struct osmo_fd *ofd) rdlen = esme->read_len - esme->read_idx; rc = read(ofd->fd, msg->tail, OSMO_MIN(rdlen, msgb_tailroom(msg))); if (rc < 0) { - LOGP(DSMPP, LOGL_ERROR, "[%s] read returned %d\n", - esme->system_id, rc); + LOGPESME(esme, LOGL_ERROR, "read returned %d\n", rc); } else if (rc == 0) { goto dead_socket; } else { @@ -282,7 +278,7 @@ static int esme_write_cb(struct osmo_fd *ofd, struct msgb *msg) esme->wqueue.bfd.fd = -1; exit(99); } else if (rc < msgb_length(msg)) { - LOGP(DSMPP, LOGL_ERROR, "[%s] Short write\n", esme->system_id); + LOGPESME(esme, LOGL_ERROR, "Short write\n"); return 0; }