Logging: Make use of Levels, clarify some messages

Up to now most logging is on LDEBUG, lets make more use of Log Levels.
reserve NOTICE for unusual events
INFO: normal call setup/teardown
DEBUG, well.. it's DEBUG

* BYE is not an Error.
* 4XX or 5XX response to INVITE is not an Error don't log as such.
* 183 does not necessarily mean "ringing".
Change those log messages for clarity.

Change-Id: Ie0014043d93303a87cbb8bb351e439ff78651cbe
This commit is contained in:
Keith Whyte 2019-08-07 02:13:06 +02:00
parent f9a0f3af42
commit b43c296f19
2 changed files with 20 additions and 20 deletions

View File

@ -422,7 +422,7 @@ static void check_rtp_create(struct mncc_connection *conn, const char *buf, int
/* TODO.. now we can continue with the call */
struct in_addr net = { .s_addr = leg->base.ip };
inet_ntop(AF_INET, &net, ip_addr, sizeof(ip_addr));
LOGP(DMNCC, LOGL_DEBUG,
LOGP(DMNCC, LOGL_INFO,
"RTP continue leg(%u) ip(%s), port(%u) pt(%u) ptm(%u)\n",
leg->callref, ip_addr, leg->base.port,
leg->base.payload_type, leg->base.payload_msg_type);
@ -515,7 +515,7 @@ static void check_setup(struct mncc_connection *conn, const char *buf, int rc)
memcpy(&leg->calling, &data->calling, sizeof(leg->calling));
memcpy(&leg->imsi, data->imsi, sizeof(leg->imsi));
LOGP(DMNCC, LOGL_DEBUG,
LOGP(DMNCC, LOGL_INFO,
"Created call(%u) with MNCC leg(%u) IMSI(%.16s)\n",
call->id, leg->callref, data->imsi);
@ -624,7 +624,7 @@ static void check_stp_cmpl_ind(struct mncc_connection *conn, const char *buf, in
if (!leg)
return;
LOGP(DMNCC, LOGL_NOTICE, "leg(%u) is now connected.\n", leg->callref);
LOGP(DMNCC, LOGL_INFO, "leg(%u) is now connected.\n", leg->callref);
stop_cmd_timer(leg, MNCC_SETUP_COMPL_IND);
leg->state = MNCC_CC_CONNECTED;
}

View File

@ -76,7 +76,7 @@ static void call_progress(struct sip_call_leg *leg, const sip_t *sip, int status
if (status == 183)
sdp_extract_sdp(leg, sip, false);
LOGP(DSIP, LOGL_NOTICE, "leg(%p) is now ringing.\n", leg);
LOGP(DSIP, LOGL_INFO, "leg(%p) is now progressing.\n", leg);
other->ring_call(other);
}
@ -98,7 +98,7 @@ static void call_connect(struct sip_call_leg *leg, const sip_t *sip)
return;
}
LOGP(DSIP, LOGL_NOTICE, "leg(%p) is now connected(%s).\n", leg, sip->sip_call_id->i_id);
LOGP(DSIP, LOGL_INFO, "leg(%p) is now connected(%s).\n", leg, sip->sip_call_id->i_id);
leg->state = SIP_CC_CONNECTED;
other->connect_call(other);
nua_ack(leg->nua_handle, TAG_END());
@ -112,7 +112,7 @@ static void new_call(struct sip_agent *agent, nua_handle_t *nh,
const char *from = NULL, *to = NULL;
char ip_addr[INET_ADDRSTRLEN];
LOGP(DSIP, LOGL_DEBUG, "Incoming call(%s) handle(%p)\n", sip->sip_call_id->i_id, nh);
LOGP(DSIP, LOGL_INFO, "Incoming call(%s) handle(%p)\n", sip->sip_call_id->i_id, nh);
if (!sdp_screen_sdp(sip)) {
LOGP(DSIP, LOGL_ERROR, "No supported codec.\n");
@ -161,7 +161,7 @@ static void new_call(struct sip_agent *agent, nua_handle_t *nh,
}
struct in_addr net = { .s_addr = leg->base.ip };
inet_ntop(AF_INET, &net, ip_addr, sizeof(ip_addr));
LOGP(DSIP, LOGL_DEBUG, "SDP Extracted: IP=(%s) PORT=(%u) PAYLOAD=(%u).\n",
LOGP(DSIP, LOGL_INFO, "SDP Extracted: IP=(%s) PORT=(%u) PAYLOAD=(%u).\n",
ip_addr,
leg->base.port,
leg->base.payload_type);
@ -190,7 +190,7 @@ static void sip_handle_reinvite(struct sip_call_leg *leg, nua_handle_t *nh, cons
uint16_t port = leg->base.port;
char ip_addr[INET_ADDRSTRLEN];
LOGP(DSIP, LOGL_NOTICE, "re-INVITE for call %s\n", sip->sip_call_id->i_id);
LOGP(DSIP, LOGL_INFO, "re-INVITE for call %s\n", sip->sip_call_id->i_id);
struct call_leg *other = call_leg_other(&leg->base);
if (!sdp_get_sdp_mode(sip, &mode)) {
@ -209,7 +209,7 @@ static void sip_handle_reinvite(struct sip_call_leg *leg, nua_handle_t *nh, cons
struct in_addr net = { .s_addr = leg->base.ip };
inet_ntop(AF_INET, &net, ip_addr, sizeof(ip_addr));
LOGP(DSIP, LOGL_NOTICE, "pre re-INVITE have IP:port (%s:%u)\n", ip_addr, leg->base.port);
LOGP(DSIP, LOGL_DEBUG, "pre re-INVITE have IP:port (%s:%u)\n", ip_addr, leg->base.port);
if (mode == sdp_sendonly) {
/* SIP side places call on HOLD */
@ -226,9 +226,9 @@ static void sip_handle_reinvite(struct sip_call_leg *leg, nua_handle_t *nh, cons
}
struct in_addr net = { .s_addr = leg->base.ip };
inet_ntop(AF_INET, &net, ip_addr, sizeof(ip_addr));
LOGP(DSIP, LOGL_NOTICE, "Media IP:port in re-INVITE: (%s:%u)\n", ip_addr, leg->base.port);
LOGP(DSIP, LOGL_DEBUG, "Media IP:port in re-INVITE: (%s:%u)\n", ip_addr, leg->base.port);
if (ip != leg->base.ip || port != leg->base.port) {
LOGP(DSIP, LOGL_NOTICE, "re-INVITE changes media connection.\n");
LOGP(DSIP, LOGL_INFO, "re-INVITE changes media connection.\n");
if (other->update_rtp)
other->update_rtp(leg->base.call->remote);
}
@ -343,13 +343,13 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
else if (status >= 300) {
struct call_leg *other = call_leg_other(&leg->base);
LOGP(DSIP, LOGL_ERROR, "leg(%p) unknown SIP status(%d), releasing.\n", leg, status);
LOGP(DSIP, LOGL_INFO, "INVITE got status(%d), releasing leg(%p).\n", status, leg);
nua_cancel(leg->nua_handle, TAG_END());
nua_handle_destroy(leg->nua_handle);
call_leg_release(&leg->base);
if (other) {
LOGP(DSIP, LOGL_DEBUG, "Releasing other leg (%p) with status(%d)\n", other, status);
LOGP(DSIP, LOGL_INFO, "Releasing MNCC leg (%p) with status(%d)\n", other, status);
other->cause = status2cause(status);
other->release_call(other);
}
@ -365,7 +365,7 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
} else if (event == nua_r_bye || event == nua_r_cancel) {
/* our bye or hang up is answered */
struct sip_call_leg *leg = (struct sip_call_leg *) hmagic;
LOGP(DSIP, LOGL_NOTICE, "leg(%p) got resp to %s\n",
LOGP(DSIP, LOGL_INFO, "leg(%p) got resp to %s\n",
leg, event == nua_r_bye ? "bye" : "cancel");
nua_handle_destroy(leg->nua_handle);
call_leg_release(&leg->base);
@ -374,7 +374,7 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
struct sip_call_leg *leg = (struct sip_call_leg *) hmagic;
struct call_leg *other = call_leg_other(&leg->base);
LOGP(DSIP, LOGL_ERROR, "leg(%p) got bye, releasing.\n", leg);
LOGP(DSIP, LOGL_INFO, "leg(%p) got bye, releasing.\n", leg);
nua_handle_destroy(leg->nua_handle);
call_leg_release(&leg->base);
@ -382,7 +382,7 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
other->release_call(other);
} else if (event == nua_i_invite) {
/* new incoming leg or re-INVITE */
LOGP(DSIP, LOGL_NOTICE, "Processing INVITE Call-ID: %s\n", sip->sip_call_id->i_id);
LOGP(DSIP, LOGL_INFO, "Processing INVITE Call-ID: %s\n", sip->sip_call_id->i_id);
if (status == 100) {
struct sip_call_leg *leg = sip_find_leg(nh);
@ -395,7 +395,7 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
struct sip_call_leg *leg;
struct call_leg *other;
LOGP(DSIP, LOGL_ERROR, "Cancelled on leg(%p)\n", hmagic);
LOGP(DSIP, LOGL_INFO, "Cancelled on leg(%p)\n", hmagic);
leg = (struct sip_call_leg *) hmagic;
other = call_leg_other(&leg->base);
@ -447,18 +447,18 @@ static void sip_release_call(struct call_leg *_leg)
* to help us here.
*/
LOGP(DSIP, LOGL_DEBUG, "%s(): Release with MNCC cause(%s)\n", __func__, gsm48_cc_cause_name(_leg->cause));
LOGP(DSIP, LOGL_INFO, "%s(): Release with MNCC cause(%s)\n", __func__, gsm48_cc_cause_name(_leg->cause));
cause2status(_leg->cause, &sip_cause, &sip_phrase, &reason_text);
snprintf(reason, sizeof reason, "Q.850;cause=%u;text=\"%s\"", _leg->cause, reason_text);
switch (leg->state) {
case SIP_CC_INITIAL:
LOGP(DSIP, LOGL_NOTICE, "Cancelling leg(%p) in initial state\n", leg);
LOGP(DSIP, LOGL_INFO, "Cancelling leg(%p) in initial state\n", leg);
nua_handle_destroy(leg->nua_handle);
call_leg_release(&leg->base);
break;
case SIP_CC_DLG_CNFD:
LOGP(DSIP, LOGL_NOTICE, "Cancelling leg(%p) in confirmed state\n", leg);
LOGP(DSIP, LOGL_INFO, "Cancelling leg(%p) in confirmed state\n", leg);
if (leg->dir == SIP_DIR_MT)
nua_cancel(leg->nua_handle, TAG_END());
else {