From 33e8a87cd7306fa365d6de0549ed2397edbf4df9 Mon Sep 17 00:00:00 2001 From: Holger Hans Peter Freyther Date: Wed, 14 Nov 2012 06:07:47 +0100 Subject: smc: Introduce an id and prefix all log messages with SMC(ID) When OpenBSC is handling more than one message at a time it is difficult to see which log message belongs to which SMC. Introduce a uint64_t id that can be set to the row_id/message_id and prefix all log messages with SMC(ID). This change is ABI and API incompatible with previous versions of libosmogsm. Example: SMC(100) instance created SMC(100) message MNSMS-EST-REQ received in state IDLE --- src/gsm/gsm0411_smc.c | 90 ++++++++++++++++++++++++++++++++++----------------- 1 file changed, 60 insertions(+), 30 deletions(-) (limited to 'src') diff --git a/src/gsm/gsm0411_smc.c b/src/gsm/gsm0411_smc.c index 4152ef1c..57431ef5 100644 --- a/src/gsm/gsm0411_smc.c +++ b/src/gsm/gsm0411_smc.c @@ -50,6 +50,7 @@ */ #include +#include #include #include #include @@ -63,14 +64,17 @@ static void cp_timer_expired(void *data); #define MAX_SMS_RETRY 2 +#define SMC_LOG_STR "SMC(%" PRIu64 ") " + /* init a new instance */ -void gsm411_smc_init(struct gsm411_smc_inst *inst, int network, +void gsm411_smc_init(struct gsm411_smc_inst *inst, uint64_t id, int network, int (*mn_recv) (struct gsm411_smc_inst *inst, int msg_type, struct msgb *msg), int (*mm_send) (struct gsm411_smc_inst *inst, int msg_type, struct msgb *msg, int cp_msg_type)) { memset(inst, 0, sizeof(*inst)); + inst->id = id; inst->network = network; inst->cp_max_retr = MAX_SMS_RETRY; inst->cp_tc1 = GSM411_TMR_TC1A_SEC / (inst->cp_max_retr + 1); @@ -78,19 +82,22 @@ void gsm411_smc_init(struct gsm411_smc_inst *inst, int network, inst->mn_recv = mn_recv; inst->mm_send = mm_send; - LOGP(DLSMS, LOGL_INFO, "New SMC instance created\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "instance created\n", inst->id); } /* clear instance */ void gsm411_smc_clear(struct gsm411_smc_inst *inst) { - LOGP(DLSMS, LOGL_INFO, "Clear SMC instance\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "clearing instance\n", inst->id); osmo_timer_del(&inst->cp_timer); /* free stored msg */ if (inst->cp_msg) { - LOGP(DLSMS, LOGL_INFO, "Dropping pending message\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "dropping pending message\n", inst->id); msgb_free(inst->cp_msg); inst->cp_msg = NULL; } @@ -120,7 +127,8 @@ const struct value_string gsm411_cp_cause_strs[] = { static void new_cp_state(struct gsm411_smc_inst *inst, enum gsm411_cp_state state) { - LOGP(DLSMS, LOGL_INFO, "New CP state %s -> %s\n", + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "new CP state %s -> %s\n", inst->id, smc_state_names[inst->cp_state], smc_state_names[state]); inst->cp_state = state; } @@ -130,7 +138,8 @@ static int gsm411_tx_cp_error(struct gsm411_smc_inst *inst, uint8_t cause) struct msgb *nmsg = gsm411_msgb_alloc(); uint8_t *causep; - LOGP(DLSMS, LOGL_NOTICE, "TX CP-ERROR, cause %d (%s)\n", cause, + LOGP(DLSMS, LOGL_NOTICE, + SMC_LOG_STR "TX CP-ERROR, cause %d (%s)\n", inst->id, cause, get_value_string(gsm411_cp_cause_strs, cause)); causep = msgb_put(nmsg, 1); @@ -146,8 +155,10 @@ static int gsm411_mnsms_est_req(struct gsm411_smc_inst *inst, struct msgb *msg) struct msgb *nmsg; if (inst->cp_msg) { - LOGP(DLSMS, LOGL_FATAL, "EST REQ, but we already have an " - "cp_msg. This should never happen, please fix!\n"); + LOGP(DLSMS, LOGL_FATAL, + SMC_LOG_STR "EST REQ, but we already have an " + "cp_msg. This should never happen, please fix!\n", + inst->id); msgb_free(inst->cp_msg); } @@ -164,7 +175,8 @@ static int gsm411_mmsms_send_msg(struct gsm411_smc_inst *inst) { struct msgb *nmsg; - LOGP(DLSMS, LOGL_INFO, "Send CP data\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "send CP data\n", inst->id); /* reset retry counter */ if (inst->cp_state != GSM411_CPS_WAIT_CP_ACK) inst->cp_retx = 0; @@ -187,8 +199,10 @@ static int gsm411_mmsms_send_msg(struct gsm411_smc_inst *inst) static int gsm411_mmsms_est_cnf(struct gsm411_smc_inst *inst, struct msgb *msg) { if (!inst->cp_msg) { - LOGP(DLSMS, LOGL_FATAL, "EST CNF, but we have no cp_msg. This " - "should never happen, please fix!\n"); + LOGP(DLSMS, LOGL_FATAL, + SMC_LOG_STR "EST CNF, but we have no cp_msg. This " + "should never happen, please fix!\n", + inst->id); return -EINVAL; } @@ -203,7 +217,9 @@ static void cp_timer_expired(void *data) if (inst->cp_retx == inst->cp_max_retr) { - LOGP(DLSMS, LOGL_INFO, "TC1* timeout, no more retries.\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "TC1* timeout, no more retries.\n", + inst->id); /* 5.3.2.1: enter idle state */ new_cp_state(inst, GSM411_CPS_IDLE); /* indicate error */ @@ -221,7 +237,8 @@ static void cp_timer_expired(void *data) return; } - LOGP(DLSMS, LOGL_INFO, "TC1* timeout, retrying...\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "TC1* timeout, retrying...\n", inst->id); inst->cp_retx++; gsm411_mmsms_est_cnf(inst, NULL); } @@ -234,7 +251,8 @@ static int gsm411_mmsms_cp_ack(struct gsm411_smc_inst *inst, struct msgb *msg) inst->cp_msg = NULL; } - LOGP(DLSMS, LOGL_INFO, "Received CP-ACK\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "received CP-ACK\n", inst->id); /* 5.3.2.1 enter MM Connection established */ new_cp_state(inst, GSM411_CPS_MM_ESTABLISHED); /* 5.3.2.1: Reset Timer TC1* */ @@ -244,7 +262,9 @@ static int gsm411_mmsms_cp_ack(struct gsm411_smc_inst *inst, struct msgb *msg) if (inst->cp_rel) { struct msgb *nmsg; - LOGP(DLSMS, LOGL_INFO, "We have pending release.\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "we have pending release.\n", + inst->id); new_cp_state(inst, GSM411_CPS_IDLE); /* release MM connection */ nmsg = gsm411_msgb_alloc(); @@ -259,7 +279,8 @@ static int gsm411_mmsms_cp_data(struct gsm411_smc_inst *inst, struct msgb *msg) struct msgb *nmsg; int mt = GSM411_MNSMS_DATA_IND; - LOGP(DLSMS, LOGL_INFO, "Received CP-DATA\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "received CP-DATA\n", inst->id); /* 5.3.1 enter MM Connection established (if idle) */ if (inst->cp_state == GSM411_CPS_IDLE) { new_cp_state(inst, GSM411_CPS_MM_ESTABLISHED); @@ -280,8 +301,10 @@ static int gsm411_mmsms_cp_data(struct gsm411_smc_inst *inst, struct msgb *msg) static int gsm411_mnsms_data_req(struct gsm411_smc_inst *inst, struct msgb *msg) { if (inst->cp_msg) { - LOGP(DLSMS, LOGL_FATAL, "DATA REQ, but we already have an " - "cp_msg. This should never happen, please fix!\n"); + LOGP(DLSMS, LOGL_FATAL, + SMC_LOG_STR "DATA REQ, but we already have an " + "cp_msg. This should never happen, please fix!\n", + inst->id); msgb_free(inst->cp_msg); } @@ -304,8 +327,8 @@ static int gsm411_mnsms_rel_req(struct gsm411_smc_inst *inst, struct msgb *msg) /* store release, until established or released */ if (inst->cp_state != GSM411_CPS_MM_ESTABLISHED) { LOGP(DLSMS, LOGL_NOTICE, - "Cannot release yet current state: %s\n", - smc_state_names[inst->cp_state]); + SMC_LOG_STR "cannot release yet current state: %s\n", + inst->id, smc_state_names[inst->cp_state]); inst->cp_rel = 1; return 0; } @@ -332,7 +355,8 @@ static int gsm411_mmsms_cp_error(struct gsm411_smc_inst *inst, struct msgb *msg) inst->cp_msg = NULL; } - LOGP(DLSMS, LOGL_INFO, "Received CP-ERROR\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "received CP-ERROR\n", inst->id); /* 5.3.4 enter idle */ new_cp_state(inst, GSM411_CPS_IDLE); /* indicate error */ @@ -352,7 +376,8 @@ static int gsm411_mmsms_rel_ind(struct gsm411_smc_inst *inst, struct msgb *msg) inst->cp_msg = NULL; } - LOGP(DLSMS, LOGL_INFO, "MM layer is released\n"); + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "MM layer is released\n", inst->id); /* 5.3.4 enter idle */ new_cp_state(inst, GSM411_CPS_IDLE); /* indicate error */ @@ -429,13 +454,15 @@ int gsm411_smc_send(struct gsm411_smc_inst *inst, int msg_type, break; } if (i == SMCDOWNSLLEN) { - LOGP(DLSMS, LOGL_NOTICE, "Message %u unhandled at this state " - "%s.\n", msg_type, smc_state_names[inst->cp_state]); + LOGP(DLSMS, LOGL_NOTICE, + SMC_LOG_STR "message %u unhandled at this state %s.\n", + inst->id, msg_type, smc_state_names[inst->cp_state]); msgb_free(msg); return 0; } - LOGP(DLSMS, LOGL_INFO, "Message %s received in state %s\n", + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "message %s received in state %s\n", inst->id, smcdownstatelist[i].name, smc_state_names[inst->cp_state]); rc = smcdownstatelist[i].rout(inst, msg); @@ -506,15 +533,17 @@ int gsm411_smc_recv(struct gsm411_smc_inst *inst, int msg_type, break; } if (i == SMCDATASLLEN) { - LOGP(DLSMS, LOGL_NOTICE, "Message 0x%x/%u unhandled at this " - "state %s.\n", msg_type, cp_msg_type, + LOGP(DLSMS, LOGL_NOTICE, + SMC_LOG_STR "message 0x%x/%u unhandled at this " + "state %s.\n", inst->id, msg_type, cp_msg_type, smc_state_names[inst->cp_state]); if (msg_type == GSM411_MMSMS_EST_IND || msg_type == GSM411_MMSMS_DATA_IND) { struct msgb *nmsg; - LOGP(DLSMS, LOGL_NOTICE, "RX Unimplemented CP " - "msg_type: 0x%02x\n", msg_type); + LOGP(DLSMS, LOGL_NOTICE, + SMC_LOG_STR "RX Unimplemented CP " + "msg_type: 0x%02x\n", inst->id, msg_type); /* 5.3.4 enter idle */ new_cp_state(inst, GSM411_CPS_IDLE); /* indicate error */ @@ -532,7 +561,8 @@ int gsm411_smc_recv(struct gsm411_smc_inst *inst, int msg_type, return 0; } - LOGP(DLSMS, LOGL_INFO, "Message %s received in state %s\n", + LOGP(DLSMS, LOGL_INFO, + SMC_LOG_STR "message %s received in state %s\n", inst->id, smcdatastatelist[i].name, smc_state_names[inst->cp_state]); rc = smcdatastatelist[i].rout(inst, msg); -- cgit v1.2.3