lapd: Always print context information when logging
Historically, OpenBSC has primarily been used with setups that have
a single E1 based BTS connected. This meant that an error message on
the E1 LAPD implicitly has to be related to that single BTS.
However, in more comprehensive setups, there may be many BTSs on many
E1 lines with many signaling slots. At this point, it's important to
know which line/timeslot/tei/sapi a given log message relates to.
This patch introduces related log context.
Change-Id: Ib81a749ae24013b17caaf5fd64ccd9acbbc3ce08
Requires: libosmocore.git Change-Id Ie6742843fff809edffcac24c4dce4edf66bc71be
Related: OS#1938
diff --git a/src/e1_input.c b/src/e1_input.c
index b3341e7..7066acf 100644
--- a/src/e1_input.c
+++ b/src/e1_input.c
@@ -312,6 +312,14 @@
return 0;
}
+void e1inp_ts_name(char *out, size_t out_len, const struct e1inp_ts *ts)
+{
+ if (ts->line->name)
+ snprintf(out, out_len, "%s:%u", ts->line->name, ts->num);
+ else
+ snprintf(out, out_len, "%u:%u", ts->line->num, ts->num);
+}
+
int e1inp_ts_config_sign(struct e1inp_ts *ts, struct e1inp_line *line)
{
if (ts->type == E1INP_TS_TYPE_SIGN && ts->line && line)
diff --git a/src/input/dahdi.c b/src/input/dahdi.c
index 6da1a02..a461f27 100644
--- a/src/input/dahdi.c
+++ b/src/input/dahdi.c
@@ -683,10 +683,13 @@
if (ret < 0)
return ret;
- if (!e1i_ts->lapd)
- e1i_ts->lapd = lapd_instance_alloc(1,
+ if (!e1i_ts->lapd) {
+ char name[32];
+ e1inp_ts_name(name, sizeof(name), e1i_ts);
+ e1i_ts->lapd = lapd_instance_alloc2(1,
dahdi_write_msg, bfd, e1inp_dlsap_up,
- e1i_ts, &lapd_profile_abis);
+ e1i_ts, &lapd_profile_abis, name);
+ }
break;
case E1INP_TS_TYPE_HDLC:
if (!bfd->fd)
diff --git a/src/input/e1d.c b/src/input/e1d.c
index 1e9f3bb..f7a0b18 100644
--- a/src/input/e1d.c
+++ b/src/input/e1d.c
@@ -254,10 +254,13 @@
}
bfd->when = BSC_FD_READ;
- if (!e1i_ts->lapd)
- e1i_ts->lapd = lapd_instance_alloc(1,
+ if (!e1i_ts->lapd) {
+ char name[32];
+ e1inp_ts_name(name, e1i_ts);
+ e1i_ts->lapd = lapd_instance_alloc2(1,
e1d_write_msg, bfd, e1inp_dlsap_up,
- e1i_ts, &lapd_profile_abis);
+ e1i_ts, &lapd_profile_abis, name);
+ }
break;
case E1INP_TS_TYPE_HDLC:
/* close/release LAPD instance, if any */
diff --git a/src/input/lapd.c b/src/input/lapd.c
index a72a19b..4bcece5 100644
--- a/src/input/lapd.c
+++ b/src/input/lapd.c
@@ -73,6 +73,15 @@
#define LAPD_SET_K(n, o) {n,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}
+#define LOGLI(li, level, fmt, args ...) \
+ LOGP(DLLAPD, level, "%s: " fmt, (li)->name, ## args)
+
+#define LOGTEI(teip, level, fmt, args ...) \
+ LOGP(DLLAPD, level, "(%s-T%u): " fmt, (teip)->li->name, (teip)->tei, ## args)
+
+#define LOGSAP(sap, level, fmt, args ...) \
+ LOGP(DLLAPD, level, "%s: " fmt, (sap)->dl.name, ## args)
+
const struct lapd_profile lapd_profile_isdn = {
.k = LAPD_SET_K(7,7),
.n200 = 3,
@@ -177,7 +186,7 @@
/* Change state of TEI */
static void lapd_tei_set_state(struct lapd_tei *teip, int newstate)
{
- LOGP(DLLAPD, LOGL_INFO, "LAPD state change on TEI %d: %s -> %s\n",
+ LOGTEI(teip, LOGL_INFO, "LAPD state change on TEI %d: %s -> %s\n",
teip->tei, lapd_tei_states[teip->state],
lapd_tei_states[newstate]);
teip->state = newstate;
@@ -223,29 +232,32 @@
{
struct lapd_sap *sap;
struct lapd_datalink *dl;
- struct lapd_instance *li;
+ struct lapd_instance *li = teip->li;
struct lapd_profile *profile;
+ char name[256];
int k;
+ snprintf(name, sizeof(name), "(%s-T%u-S%u)", li->name, teip->tei, sapi);
+
sap = talloc_zero(teip, struct lapd_sap);
if (!sap)
return NULL;
LOGP(DLLAPD, LOGL_NOTICE,
- "LAPD Allocating SAP for SAPI=%u / TEI=%u (dl=%p, sap=%p)\n",
- sapi, teip->tei, &sap->dl, sap);
+ "%s: LAPD Allocating SAP for SAPI=%u / TEI=%u (dl=%p, sap=%p)\n",
+ name, sapi, teip->tei, &sap->dl, sap);
sap->sapi = sapi;
sap->tei = teip;
dl = &sap->dl;
- li = teip->li;
profile = &li->profile;
k = profile->k[sapi & 0x3f];
- LOGP(DLLAPD, LOGL_NOTICE, "k=%d N200=%d N201=%d T200=%d.%d T203=%d.%d"
- "\n", k, profile->n200, profile->n201, profile->t200_sec,
+ LOGP(DLLAPD, LOGL_NOTICE, "%s: k=%d N200=%d N201=%d T200=%d.%d T203=%d.%d\n",
+ name, k, profile->n200, profile->n201, profile->t200_sec,
profile->t200_usec, profile->t203_sec, profile->t203_usec);
lapd_dl_init(dl, k, 128, profile->n201);
+ lapd_dl_set_name(dl, name);
dl->use_sabme = 1; /* use SABME instead of SABM (GSM) */
dl->send_ph_data_req = send_ph_data_req;
dl->send_dlsap = send_dlsap;
@@ -269,7 +281,7 @@
/* Free SAP instance, including the datalink */
static void lapd_sap_free(struct lapd_sap *sap)
{
- LOGP(DLLAPD, LOGL_NOTICE,
+ LOGSAP(sap, LOGL_NOTICE,
"LAPD Freeing SAP for SAPI=%u / TEI=%u (dl=%p, sap=%p)\n",
sap->sapi, sap->tei->tei, &sap->dl, sap);
@@ -306,7 +318,7 @@
struct msgb *msg;
if (len < 5) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD TEIMGR frame receive len %d < 5"
+ LOGLI(li, LOGL_ERROR, "LAPD TEIMGR frame receive len %d < 5"
", ignoring\n", len);
return -EINVAL;
};
@@ -327,7 +339,7 @@
teip = teip_from_tei(li, action);
if (!teip) {
- LOGP(DLLAPD, LOGL_INFO, "TEI MGR: New TEI %u\n",
+ LOGLI(li, LOGL_INFO, "TEI MGR: New TEI %u\n",
action);
teip = lapd_tei_alloc(li, action);
if (!teip)
@@ -344,16 +356,14 @@
/* write to PCAP file, if enabled. */
osmo_pcap_lapd_write(li->pcap_fd, OSMO_LAPD_PCAP_OUTPUT, msg);
- LOGP(DLLAPD, LOGL_DEBUG, "TX: %s\n",
- osmo_hexdump(msg->data, msg->len));
+ LOGTEI(teip, LOGL_DEBUG, "TX: %s\n", osmo_hexdump(msg->data, msg->len));
li->transmit_cb(msg, li->transmit_cbdata);
if (teip->state == LAPD_TEI_NONE)
lapd_tei_set_state(teip, LAPD_TEI_ASSIGNED);
break;
default:
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD TEIMGR: unknown mt %x "
- "action %x\n", mt, action);
+ LOGLI(li, LOGL_NOTICE, "LAPD TEIMGR: unknown mt %x action %x\n", mt, action);
break;
};
@@ -372,10 +382,9 @@
/* write to PCAP file, if enabled. */
osmo_pcap_lapd_write(li->pcap_fd, OSMO_LAPD_PCAP_INPUT, msg);
- LOGP(DLLAPD, LOGL_DEBUG, "RX: %s\n", osmo_hexdump(msg->data, msg->len));
+ LOGLI(li, LOGL_DEBUG, "RX: %s\n", osmo_hexdump(msg->data, msg->len));
if (msg->len < 2) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD frame receive len %d < 2, "
- "ignoring\n", msg->len);
+ LOGLI(li, LOGL_ERROR, "LAPD frame receive len %d < 2, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
};
@@ -390,7 +399,7 @@
lctx.lpd = 0;
if (!LAPD_ADDR_EA(msg->l2h[i])) {
if (msg->len < 3) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD frame with TEI receive "
+ LOGLI(li, LOGL_ERROR, "LAPD frame with TEI receive "
"len %d < 3, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
@@ -405,13 +414,13 @@
lctx.n_send = LAPD_CTRL_I_Ns(msg->l2h[i]);
i++;
if (msg->len < 3 && i == 2) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD I frame without TEI "
+ LOGLI(li, LOGL_ERROR, "LAPD I frame without TEI "
"receive len %d < 3, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
};
if (msg->len < 4 && i == 3) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD I frame with TEI "
+ LOGLI(li, LOGL_ERROR, "LAPD I frame with TEI "
"receive len %d < 4, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
@@ -423,13 +432,13 @@
lctx.s_u = LAPD_CTRL_S_BITS(msg->l2h[i]);
i++;
if (msg->len < 3 && i == 2) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD S frame without TEI "
+ LOGLI(li, LOGL_ERROR, "LAPD S frame without TEI "
"receive len %d < 3, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
};
if (msg->len < 4 && i == 3) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD S frame with TEI "
+ LOGLI(li, LOGL_ERROR, "LAPD S frame with TEI "
"receive len %d < 4, ignoring\n", msg->len);
*error = LAPD_ERR_BAD_LEN;
return -EINVAL;
@@ -458,14 +467,14 @@
/* resolve TEI and SAPI */
teip = teip_from_tei(li, lctx.tei);
if (!teip) {
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD Unknown TEI %u\n", lctx.tei);
+ LOGLI(li, LOGL_NOTICE, "LAPD Unknown TEI %u\n", lctx.tei);
*error = LAPD_ERR_UNKNOWN_TEI;
msgb_free(msg);
return -EINVAL;
}
sap = lapd_sap_find(teip, lctx.sapi);
if (!sap) {
- LOGP(DLLAPD, LOGL_INFO, "LAPD No SAP for TEI=%u / SAPI=%u, "
+ LOGTEI(teip, LOGL_INFO, "LAPD No SAP for TEI=%u / SAPI=%u, "
"allocating\n", lctx.tei, lctx.sapi);
sap = lapd_sap_alloc(teip, lctx.sapi);
if (!sap) {
@@ -478,7 +487,7 @@
lctx.n201 = lctx.dl->maxf;
if (msg->len > lctx.n201) {
- LOGP(DLLAPD, LOGL_ERROR, "message len %d > N201(%d) "
+ LOGSAP(sap, LOGL_ERROR, "message len %d > N201(%d) "
"(discarding)\n", msg->len, lctx.n201);
msgb_free(msg);
*error = LAPD_ERR_BAD_LEN;
@@ -509,8 +518,7 @@
if (!sap)
return -ENOMEM;
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD DL-ESTABLISH request TEI=%d SAPI=%d\n",
- tei, sapi);
+ LOGSAP(sap, LOGL_NOTICE, "LAPD DL-ESTABLISH request TEI=%d SAPI=%d\n", tei, sapi);
/* prepare prim */
msg = msgb_alloc_headroom(56, 56, "DL EST");
@@ -537,8 +545,7 @@
if (!sap)
return -ENODEV;
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD DL-RELEASE request TEI=%d SAPI=%d\n",
- tei, sapi);
+ LOGSAP(sap, LOGL_NOTICE, "LAPD DL-RELEASE request TEI=%d SAPI=%d\n", tei, sapi);
/* prepare prim */
msg = msgb_alloc_headroom(56, 56, "DL REL");
@@ -558,16 +565,14 @@
struct osmo_dlsap_prim dp;
if (!teip) {
- LOGP(DLLAPD, LOGL_ERROR, "LAPD Cannot transmit on "
- "non-existing TEI %u\n", tei);
+ LOGLI(li, LOGL_ERROR, "LAPD Cannot transmit on non-existing TEI %u\n", tei);
msgb_free(msg);
return;
}
sap = lapd_sap_find(teip, sapi);
if (!sap) {
- LOGP(DLLAPD, LOGL_INFO, "LAPD Tx on unknown SAPI=%u "
- "in TEI=%u\n", sapi, tei);
+ LOGTEI(teip, LOGL_INFO, "LAPD Tx on unknown SAPI=%u in TEI=%u\n", sapi, tei);
msgb_free(msg);
return;
}
@@ -625,7 +630,7 @@
osmo_pcap_lapd_write(li->pcap_fd, OSMO_LAPD_PCAP_OUTPUT, msg);
/* forward frame to L1 */
- LOGP(DLLAPD, LOGL_DEBUG, "TX: %s\n", osmo_hexdump(msg->data, msg->len));
+ LOGDL(dl, LOGL_DEBUG, "TX: %s\n", osmo_hexdump(msg->data, msg->len));
li->transmit_cb(msg, li->transmit_cbdata);
return 0;
@@ -648,11 +653,11 @@
switch (dp->oph.primitive) {
case PRIM_DL_EST:
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD DL-ESTABLISH %s TEI=%d "
+ LOGDL(dl, LOGL_NOTICE, "LAPD DL-ESTABLISH %s TEI=%d "
"SAPI=%d\n", op, lctx->tei, lctx->sapi);
break;
case PRIM_DL_REL:
- LOGP(DLLAPD, LOGL_NOTICE, "LAPD DL-RELEASE %s TEI=%d "
+ LOGDL(dl, LOGL_NOTICE, "LAPD DL-RELEASE %s TEI=%d "
"SAPI=%d\n", op, lctx->tei, lctx->sapi);
lapd_sap_free(sap);
/* note: sap and dl is now gone, don't use it anymore */
@@ -667,11 +672,11 @@
}
/* Allocate a new LAPD instance */
-struct lapd_instance *lapd_instance_alloc(int network_side,
+struct lapd_instance *lapd_instance_alloc2(int network_side,
void (*tx_cb)(struct msgb *msg, void *cbdata), void *tx_cbdata,
- void (*rx_cb)(struct osmo_dlsap_prim *odp, uint8_t tei, uint8_t sapi,
+ void (*rx_cb)(struct osmo_dlsap_prim *odp, uint8_t tei, uint8_t sapi,
void *rx_cbdata), void *rx_cbdata,
- const struct lapd_profile *profile)
+ const struct lapd_profile *profile, const char *name)
{
struct lapd_instance *li;
@@ -685,6 +690,7 @@
li->receive_cb = rx_cb;
li->receive_cbdata = rx_cbdata;
li->pcap_fd = -1;
+ li->name = talloc_strdup(li, name);
memcpy(&li->profile, profile, sizeof(li->profile));
INIT_LLIST_HEAD(&li->tei_list);
@@ -692,6 +698,16 @@
return li;
}
+struct lapd_instance *lapd_instance_alloc(int network_side,
+ void (*tx_cb)(struct msgb *msg, void *cbdata), void *tx_cbdata,
+ void (*rx_cb)(struct osmo_dlsap_prim *odp, uint8_t tei, uint8_t sapi,
+ void *rx_cbdata), void *rx_cbdata,
+ const struct lapd_profile *profile)
+{
+ return lapd_instance_alloc2(network_side, tx_cbdata, tx_cb, rx_cb, rx_cbdata, profile, NULL);
+}
+
+
/* Change lapd-profile on the fly (use with caution!) */
void lapd_instance_set_profile(struct lapd_instance *li,
const struct lapd_profile *profile)
diff --git a/src/input/misdn.c b/src/input/misdn.c
index fef1c0f..564d008 100644
--- a/src/input/misdn.c
+++ b/src/input/misdn.c
@@ -636,10 +636,12 @@
switch (e1i_ts->type) {
case E1INP_TS_TYPE_SIGN:
if (mline->use_userspace_lapd) {
+ char name[32];
addr.channel = ts;
- e1i_ts->lapd = lapd_instance_alloc(1,
+ e1inp_ts_name(name, sizeof(name), e1i_ts);
+ e1i_ts->lapd = lapd_instance_alloc2(1,
misdn_write_msg, bfd, e1inp_dlsap_up,
- e1i_ts, &lapd_profile_abis);
+ e1i_ts, &lapd_profile_abis, name);
} else {
addr.channel = 0;
/* SAPI not supported yet in kernel */
diff --git a/src/input/unixsocket.c b/src/input/unixsocket.c
index 1d25ddf..cfb4979 100644
--- a/src/input/unixsocket.c
+++ b/src/input/unixsocket.c
@@ -287,10 +287,12 @@
/* Set line parameter */
for (i = 0; i < ARRAY_SIZE(line->ts); i++) {
struct e1inp_ts *e1i_ts = &line->ts[i];
+ char name[32];
if (!e1i_ts->lapd) {
- e1i_ts->lapd = lapd_instance_alloc(1,
+ e1inp_ts_name(name, sizeof(name), e1i_ts);
+ e1i_ts->lapd = lapd_instance_alloc2(1,
unixsocket_write_msg_lapd_cb, &config->fd,
- e1inp_dlsap_up, e1i_ts, &lapd_profile_abis);
+ e1inp_dlsap_up, e1i_ts, &lapd_profile_abis, name);
}
}