diff options
| -rw-r--r-- | src/gsm/lapd_core.c | 334 |
1 files changed, 190 insertions, 144 deletions
diff --git a/src/gsm/lapd_core.c b/src/gsm/lapd_core.c index bf5c388a..84b1828d 100644 --- a/src/gsm/lapd_core.c +++ b/src/gsm/lapd_core.c @@ -197,7 +197,7 @@ static void lapd_start_t200(struct lapd_datalink *dl) { if (osmo_timer_pending(&dl->t200)) return; - LOGP(DLLAPD, LOGL_INFO, "start T200\n"); + LOGP(DLLAPD, LOGL_INFO, "start T200 (dl=%p)\n", dl); osmo_timer_schedule(&dl->t200, dl->t200_sec, dl->t200_usec); } @@ -205,7 +205,7 @@ static void lapd_start_t203(struct lapd_datalink *dl) { if (osmo_timer_pending(&dl->t203)) return; - LOGP(DLLAPD, LOGL_INFO, "start T203\n"); + LOGP(DLLAPD, LOGL_INFO, "start T203 (dl=%p)\n", dl); osmo_timer_schedule(&dl->t203, dl->t203_sec, dl->t203_usec); } @@ -213,7 +213,7 @@ static void lapd_stop_t200(struct lapd_datalink *dl) { if (!osmo_timer_pending(&dl->t200)) return; - LOGP(DLLAPD, LOGL_INFO, "stop T200\n"); + LOGP(DLLAPD, LOGL_INFO, "stop T200 (dl=%p)\n", dl); osmo_timer_del(&dl->t200); } @@ -221,14 +221,14 @@ static void lapd_stop_t203(struct lapd_datalink *dl) { if (!osmo_timer_pending(&dl->t203)) return; - LOGP(DLLAPD, LOGL_INFO, "stop T203\n"); + LOGP(DLLAPD, LOGL_INFO, "stop T203 (dl=%p)\n", dl); osmo_timer_del(&dl->t203); } static void lapd_dl_newstate(struct lapd_datalink *dl, uint32_t state) { - LOGP(DLLAPD, LOGL_INFO, "new state %s -> %s\n", - lapd_state_names[dl->state], lapd_state_names[state]); + LOGP(DLLAPD, LOGL_INFO, "new state %s -> %s (dl=%p)\n", + lapd_state_names[dl->state], lapd_state_names[state], dl); if (state != LAPD_STATE_MF_EST && dl->state == LAPD_STATE_MF_EST) { /* stop T203 on leaving MF EST state, if running */ @@ -289,7 +289,8 @@ void lapd_dl_init(struct lapd_datalink *dl, uint8_t k, uint8_t v_range, } LOGP(DLLAPD, LOGL_INFO, "Init DL layer: sequence range = %d, k = %d, " - "history range = %d\n", dl->v_range, dl->k, dl->range_hist); + "history range = %d (dl=%p)\n", dl->v_range, dl->k, + dl->range_hist, dl); lapd_dl_newstate(dl, LAPD_STATE_IDLE); @@ -304,7 +305,7 @@ void lapd_dl_reset(struct lapd_datalink *dl) { if (dl->state == LAPD_STATE_IDLE) return; - LOGP(DLLAPD, LOGL_INFO, "Resetting LAPDm instance\n"); + LOGP(DLLAPD, LOGL_INFO, "Resetting LAPDm instance (dl=%p)\n", dl); /* enter idle state (and remove eventual cont_res) */ lapd_dl_newstate(dl, LAPD_STATE_IDLE); /* flush buffer */ @@ -378,8 +379,9 @@ static int mdl_error(uint8_t cause, struct lapd_msg_ctx *lctx) struct lapd_datalink *dl = lctx->dl; struct osmo_dlsap_prim dp; - LOGP(DLLAPD, LOGL_NOTICE, "sending MDL-ERROR-IND cause %s\n", - rsl_rlm_cause_name(cause)); + LOGP(DLLAPD, LOGL_NOTICE, + "sending MDL-ERROR-IND cause %d from state %s (dl=%p)\n", + cause, lapd_state_names[dl->state], dl); osmo_prim_init(&dp.oph, 0, PRIM_MDL_ERROR, PRIM_OP_INDICATION, NULL); dp.u.error_ind.cause = cause; return dl->send_dlsap(&dp, lctx); @@ -534,6 +536,8 @@ static int lapd_reestablish(struct lapd_datalink *dl) struct osmo_dlsap_prim dp; struct msgb *msg; + LOGP(DLLAPD, LOGL_DEBUG, "lapd reestablish (dl=%p)\n", dl); + msg = lapd_msgb_alloc(0, "DUMMY"); osmo_prim_init(&dp.oph, 0, PRIM_DL_EST, PRIM_OP_REQUEST, msg); @@ -545,8 +549,8 @@ static void lapd_t200_cb(void *data) { struct lapd_datalink *dl = data; - LOGP(DLLAPD, LOGL_INFO, "Timeout T200 (%p) state=%d\n", dl, - (int) dl->state); + LOGP(DLLAPD, LOGL_INFO, "Timeout T200 state=%s (dl=%p)\n", + lapd_state_names[dl->state], dl); switch (dl->state) { case LAPD_STATE_SABM_SENT: @@ -615,7 +619,7 @@ static void lapd_t200_cb(void *data) struct lapd_msg_ctx nctx; LOGP(DLLAPD, LOGL_INFO, "retransmit last frame" - " V(S)=%d\n", vs); + " V(S)=%d (dl=%p)\n", vs, dl); /* Create I frame (segment) from tx_hist */ memcpy(&nctx, &dl->lctx, sizeof(nctx)); /* keep nctx.ldp */ @@ -647,7 +651,7 @@ static void lapd_t200_cb(void *data) lapd_send_rnr(&dl->lctx, 1, 1); } else { LOGP(DLLAPD, LOGL_INFO, "unhandled, " - "pls. fix\n"); + "pls. fix (dl=%p)\n", dl); } } /* restart T200 (PH-READY-TO-SEND) */ @@ -659,13 +663,13 @@ static void lapd_t200_cb(void *data) if (!dl->reestablish) break; LOGP(DLLAPD, LOGL_NOTICE, "N200 reached, performing " - "reestablishment.\n"); + "reestablishment. (dl=%p)\n", dl); lapd_reestablish(dl); } break; default: LOGP(DLLAPD, LOGL_INFO, "T200 expired in unexpected " - "dl->state %d\n", (int) dl->state); + "dl->state %s (dl=%p)\n", lapd_state_names[dl->state], dl); } } @@ -674,12 +678,12 @@ static void lapd_t203_cb(void *data) { struct lapd_datalink *dl = data; - LOGP(DLLAPD, LOGL_INFO, "Timeout T203 (%p) state=%d\n", dl, - (int) dl->state); + LOGP(DLLAPD, LOGL_INFO, "Timeout T203 state=%s (dl=%p)\n", + lapd_state_names[dl->state], dl); if (dl->state != LAPD_STATE_MF_EST) { LOGP(DLLAPD, LOGL_ERROR, "T203 fired outside MF EST state, " - "please fix!\n"); + "please fix! (dl=%p)\n", dl); return; } @@ -689,11 +693,13 @@ static void lapd_t203_cb(void *data) lapd_dl_newstate(dl, LAPD_STATE_TIMER_RECOV); /* transmit a supervisory command with P bit set to 1 as follows: */ if (!dl->own_busy) { - LOGP(DLLAPD, LOGL_INFO, "transmit an RR poll command\n"); + LOGP(DLLAPD, LOGL_INFO, + "transmit an RR poll command (dl=%p)\n", dl); /* Send RR with P=1 */ lapd_send_rr(&dl->lctx, 1, 1); } else { - LOGP(DLLAPD, LOGL_INFO, "transmit an RNR poll command\n"); + LOGP(DLLAPD, LOGL_INFO, + "transmit an RNR poll command (dl=%p)\n", dl); /* Send RNR with P=1 */ lapd_send_rnr(&dl->lctx, 1, 1); } @@ -743,7 +749,7 @@ static void lapd_acknowledge(struct lapd_msg_ctx *lctx) */ if (sub_mod(nr, dl->v_ack, dl->v_range) > sub_mod(dl->v_send, dl->v_ack, dl->v_range)) { - LOGP(DLLAPD, LOGL_NOTICE, "N(R) sequence error\n"); + LOGP(DLLAPD, LOGL_NOTICE, "N(R) sequence error (dl=%p)\n", dl); mdl_error(MDL_CAUSE_SEQ_ERR, lctx); } } @@ -756,7 +762,7 @@ static void lapd_acknowledge(struct lapd_msg_ctx *lctx) if (t200_reset && !rej) { if (dl->tx_hist[sub_mod(dl->v_send, 1, dl->range_hist)].msg) { LOGP(DLLAPD, LOGL_INFO, "start T200, due to unacked I " - "frame(s)\n"); + "frame(s) (dl=%p)\n", dl); lapd_start_t200(dl); } } @@ -789,13 +795,14 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) prim = PRIM_DL_EST; op = PRIM_OP_INDICATION; - LOGP(DLLAPD, LOGL_INFO, "SABM(E) received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "SABM(E) received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* 5.7.1 */ dl->seq_err_cond = 0; /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.resp) { - LOGP(DLLAPD, LOGL_ERROR, "SABM response error\n"); + LOGP(DLLAPD, LOGL_ERROR, + "SABM response error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -805,7 +812,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) * set, AN MDL-ERROR-INDICATION is sent to MM. */ if (lctx->more || length > lctx->n201) { - LOGP(DLLAPD, LOGL_ERROR, "SABM too large error\n"); + LOGP(DLLAPD, LOGL_ERROR, + "SABM too large error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_UFRM_INC_PARAM, lctx); return -EIO; @@ -816,7 +824,7 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) break; case LAPD_STATE_MF_EST: LOGP(DLLAPD, LOGL_INFO, "SABM command, multiple " - "frame established state\n"); + "frame established state (dl=%p)\n", dl); /* If link is lost on the remote side, we start over * and send DL-ESTABLISH indication again. */ /* Additionally, continue in case of content resoltion @@ -829,13 +837,13 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* If no content resolution, this is a * re-establishment. */ LOGP(DLLAPD, LOGL_INFO, - "Remote reestablish\n"); + "Remote reestablish (dl=%p)\n", dl); break; } if (!dl->cont_res) { LOGP(DLLAPD, LOGL_INFO, "SABM command not " - "allowed in state %s\n", - lapd_state_names[dl->state]); + "allowed in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); mdl_error(MDL_CAUSE_SABM_MF, lctx); msgb_free(msg); return 0; @@ -848,8 +856,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) if (memcmp(dl->cont_res->data, msg->data, length)) { LOGP(DLLAPD, LOGL_INFO, "Another SABM " - "with diffrent content - " - "ignoring!\n"); + "with diffrent content - " + "ignoring! (dl=%p)\n", dl); msgb_free(msg); return 0; } @@ -872,8 +880,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* check for contention resoultion */ if (dl->tx_hist[0].msg && dl->tx_hist[0].msg->len) { LOGP(DLLAPD, LOGL_NOTICE, "SABM not allowed " - "during contention resolution (state %s)\n", - lapd_state_names[dl->state]); + "during contention resolution (state=%s, dl=%p)\n", + lapd_state_names[dl->state], dl); mdl_error(MDL_CAUSE_SABM_INFO_NOTALL, lctx); } lapd_send_ua(lctx, length, msg->l3h); @@ -899,7 +907,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) dl->cont_res = lapd_msgb_alloc(length, "CONT RES"); memcpy(msgb_put(dl->cont_res, length), msg->l3h, length); - LOGP(DLLAPD, LOGL_NOTICE, "Store content res.\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "Store content res. (dl=%p)\n", dl); } /* send notification to L3 */ if (length == 0) { @@ -913,11 +922,12 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) } break; case LAPD_U_DM: - LOGP(DLLAPD, LOGL_INFO, "DM received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "DM received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.cmd) { - LOGP(DLLAPD, LOGL_ERROR, "DM command error\n"); + LOGP(DLLAPD, LOGL_ERROR, + "DM command error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -935,12 +945,12 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) case LAPD_STATE_MF_EST: if (lctx->p_f) { LOGP(DLLAPD, LOGL_INFO, "unsolicited DM " - "response\n"); + "response (dl=%p)\n", dl); mdl_error(MDL_CAUSE_UNSOL_DM_RESP, lctx); } else { LOGP(DLLAPD, LOGL_INFO, "unsolicited DM " "response, multiple frame established " - "state\n"); + "state (dl=%p)\n", dl); mdl_error(MDL_CAUSE_UNSOL_DM_RESP_MF, lctx); /* reestablish */ if (!dl->reestablish) { @@ -948,7 +958,7 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) return 0; } LOGP(DLLAPD, LOGL_NOTICE, "Performing " - "reestablishment.\n"); + "reestablishment. (dl=%p)\n", dl); lapd_reestablish(dl); } msgb_free(msg); @@ -958,14 +968,14 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) if (!lctx->p_f) { LOGP(DLLAPD, LOGL_INFO, "unsolicited DM " "response, multiple frame established " - "state\n"); + "state (dl=%p)\n", dl); mdl_error(MDL_CAUSE_UNSOL_DM_RESP_MF, lctx); msgb_free(msg); /* reestablish */ if (!dl->reestablish) return 0; LOGP(DLLAPD, LOGL_NOTICE, "Performing " - "reestablishment.\n"); + "reestablishment. (dl=%p)\n", dl); return lapd_reestablish(dl); } break; @@ -983,7 +993,7 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.4.5 all other frame types shall be discarded */ default: LOGP(DLLAPD, LOGL_INFO, "unsolicited DM response! " - "(discarding)\n"); + "(discarding) (dl=%p)\n", dl); msgb_free(msg); return 0; } @@ -995,11 +1005,11 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) msgb_free(msg); break; case LAPD_U_UI: - LOGP(DLLAPD, LOGL_INFO, "UI received\n"); + LOGP(DLLAPD, LOGL_INFO, "UI received (dl=%p)\n", dl); /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.resp) { LOGP(DLLAPD, LOGL_ERROR, "UI indicates response " - "error\n"); + "error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1010,8 +1020,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) */ if (length > lctx->n201 || lctx->more) { LOGP(DLLAPD, LOGL_ERROR, "UI too large error " - "(%d > N201(%d) or M=%d)\n", length, - lctx->n201, lctx->more); + "(%d > N201(%d) or M=%d) (dl=%p)\n", length, + lctx->n201, lctx->more, dl); msgb_free(msg); mdl_error(MDL_CAUSE_UFRM_INC_PARAM, lctx); return -EIO; @@ -1022,7 +1032,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.3.3 UI frames received with the length indicator * set to "0" shall be ignored */ - LOGP(DLLAPD, LOGL_INFO, "length=0 (discarding)\n"); + LOGP(DLLAPD, LOGL_INFO, + "length=0 (discarding) (dl=%p)\n", dl); msgb_free(msg); return 0; } @@ -1034,8 +1045,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) prim = PRIM_DL_REL; op = PRIM_OP_INDICATION; - LOGP(DLLAPD, LOGL_INFO, "DISC received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "DISC received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* flush tx and send buffers */ lapd_dl_flush_tx(dl); lapd_dl_flush_send(dl); @@ -1043,7 +1054,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) dl->seq_err_cond = 0; /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.resp) { - LOGP(DLLAPD, LOGL_ERROR, "DISC response error\n"); + LOGP(DLLAPD, LOGL_ERROR, + "DISC response error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1055,19 +1067,21 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) * parameters" is sent to the mobile management entity. */ LOGP(DLLAPD, LOGL_ERROR, - "U frame iwth incorrect parameters "); + "U frame iwth incorrect parameters (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_UFRM_INC_PARAM, lctx); return -EIO; } switch (dl->state) { case LAPD_STATE_IDLE: - LOGP(DLLAPD, LOGL_INFO, "DISC in idle state\n"); + LOGP(DLLAPD, LOGL_INFO, + "DISC in idle state (dl=%p)\n", dl); /* send DM with F=P */ msgb_free(msg); return lapd_send_dm(lctx); case LAPD_STATE_SABM_SENT: - LOGP(DLLAPD, LOGL_INFO, "DISC in SABM state\n"); + LOGP(DLLAPD, LOGL_INFO, + "DISC in SABM state (dl=%p)\n", dl); /* 5.4.6.2 send DM with F=P */ lapd_send_dm(lctx); /* stop Timer T200 */ @@ -1079,10 +1093,12 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) lctx); case LAPD_STATE_MF_EST: case LAPD_STATE_TIMER_RECOV: - LOGP(DLLAPD, LOGL_INFO, "DISC in est state\n"); + LOGP(DLLAPD, LOGL_INFO, + "DISC in est state (dl=%p)\n", dl); break; case LAPD_STATE_DISC_SENT: - LOGP(DLLAPD, LOGL_INFO, "DISC in disc state\n"); + LOGP(DLLAPD, LOGL_INFO, + "DISC in disc state (dl=%p)\n", dl); prim = PRIM_DL_REL; op = PRIM_OP_CONFIRM; break; @@ -1102,12 +1118,12 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) msgb_free(msg); break; case LAPD_U_UA: - LOGP(DLLAPD, LOGL_INFO, "UA received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "UA received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.cmd) { LOGP(DLLAPD, LOGL_ERROR, "UA indicates command " - "error\n"); + "error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1117,7 +1133,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) * set, AN MDL-ERROR-INDICATION is sent to MM. */ if (lctx->more || length > lctx->n201) { - LOGP(DLLAPD, LOGL_ERROR, "UA too large error\n"); + LOGP(DLLAPD, LOGL_ERROR, + "UA too large error (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_UFRM_INC_PARAM, lctx); return -EIO; @@ -1127,7 +1144,8 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.4.1.2 A UA response with the F bit set to "0" * shall be ignored. */ - LOGP(DLLAPD, LOGL_INFO, "F=0 (discarding)\n"); + LOGP(DLLAPD, LOGL_INFO, + "F=0 (discarding) (dl=%p)\n", dl); msgb_free(msg); return 0; } @@ -1137,12 +1155,13 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) case LAPD_STATE_MF_EST: case LAPD_STATE_TIMER_RECOV: LOGP(DLLAPD, LOGL_INFO, "unsolicited UA response! " - "(discarding)\n"); + "(discarding) (dl=%p)\n", dl); mdl_error(MDL_CAUSE_UNSOL_UA_RESP, lctx); msgb_free(msg); return 0; case LAPD_STATE_DISC_SENT: - LOGP(DLLAPD, LOGL_INFO, "UA in disconnect state\n"); + LOGP(DLLAPD, LOGL_INFO, + "UA in disconnect state (dl=%p)\n", dl); /* stop Timer T200 */ lapd_stop_t200(dl); /* go to idle state */ @@ -1156,11 +1175,11 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.4.5 all other frame types shall be discarded */ default: LOGP(DLLAPD, LOGL_INFO, "unsolicited UA response! " - "(discarding)\n"); + "(discarding) (dl=%p)\n", dl); msgb_free(msg); return 0; } - LOGP(DLLAPD, LOGL_INFO, "UA in SABM state\n"); + LOGP(DLLAPD, LOGL_INFO, "UA in SABM state (dl=%p)\n", dl); /* stop Timer T200 */ lapd_stop_t200(dl); /* compare UA with SABME if contention resolution is applied */ @@ -1169,7 +1188,7 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) || !!memcmp(dl->tx_hist[0].msg->data, msg->l3h, length)) { LOGP(DLLAPD, LOGL_INFO, "**** UA response " - "mismatches ****\n"); + "mismatches **** (dl=%p)\n", dl); rc = send_dl_simple(PRIM_DL_REL, PRIM_OP_INDICATION, lctx); msgb_free(msg); @@ -1193,19 +1212,22 @@ static int lapd_rx_u(struct msgb *msg, struct lapd_msg_ctx *lctx) msgb_free(msg); break; case LAPD_U_FRMR: - LOGP(DLLAPD, LOGL_NOTICE, "Frame reject received\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "Frame reject received (dl=%p)\n", dl); /* send MDL ERROR INIDCATION to L3 */ mdl_error(MDL_CAUSE_FRMR, lctx); msgb_free(msg); /* reestablish */ if (!dl->reestablish) break; - LOGP(DLLAPD, LOGL_NOTICE, "Performing reestablishment.\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "Performing reestablishment. (dl=%p)\n", dl); rc = lapd_reestablish(dl); break; default: /* G.3.1 */ - LOGP(DLLAPD, LOGL_NOTICE, "Unnumbered frame not allowed.\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "Unnumbered frame not allowed. (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1225,7 +1247,7 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) * primitive with cause "S frame with incorrect * parameters" is sent to the mobile management entity. */ LOGP(DLLAPD, LOGL_ERROR, - "S frame with incorrect parameters\n"); + "S frame with incorrect parameters (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_SFRM_INC_PARAM, lctx); return -EIO; @@ -1235,7 +1257,8 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) && lctx->p_f && dl->state != LAPD_STATE_TIMER_RECOV) { /* 5.4.2.2: Inidcate error on supervisory reponse F=1 */ - LOGP(DLLAPD, LOGL_NOTICE, "S frame response with F=1 error\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "S frame response with F=1 error (dl=%p)\n", dl); mdl_error(MDL_CAUSE_UNSOL_SPRV_RESP, lctx); } @@ -1248,14 +1271,15 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) /* fall though */ case LAPD_STATE_SABM_SENT: case LAPD_STATE_DISC_SENT: - LOGP(DLLAPD, LOGL_NOTICE, "S frame ignored in this state\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "S frame ignored in this state (dl=%p)\n", dl); msgb_free(msg); return 0; } switch (lctx->s_u) { case LAPD_S_RR: - LOGP(DLLAPD, LOGL_INFO, "RR received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "RR received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* 5.5.3.1: Acknowlege all tx frames up the the N(R)-1 */ lapd_acknowledge(lctx); @@ -1264,9 +1288,9 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) && lctx->p_f) { if (!dl->own_busy && !dl->seq_err_cond) { LOGP(DLLAPD, LOGL_INFO, "RR frame command " - "with polling bit set and we are not " - "busy, so we reply with RR frame " - "response\n"); + "with polling bit set and we are not " + "busy, so we reply with RR frame " + "response (dl=%p)\n", dl); lapd_send_rr(lctx, 1, 0); /* NOTE: In case of sequence error condition, * the REJ frame has been transmitted when @@ -1275,8 +1299,9 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) */ } else if (dl->own_busy) { LOGP(DLLAPD, LOGL_INFO, "RR frame command " - "with polling bit set and we are busy, " - "so we reply with RR frame response\n"); + "with polling bit set and we are busy, " + "so we reply with RR frame response (dl=%p)\n", + dl); lapd_send_rnr(lctx, 1, 0); } } else if (lctx->cr == dl->cr.rem2loc.resp @@ -1284,7 +1309,7 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) && dl->state == LAPD_STATE_TIMER_RECOV) { LOGP(DLLAPD, LOGL_INFO, "RR response with F==1, " "and we are in timer recovery state, so " - "we leave that state\n"); + "we leave that state (dl=%p)\n", dl); /* V(S) to the N(R) in the RR frame */ dl->v_send = lctx->n_recv; /* stop Timer T200 */ @@ -1297,8 +1322,8 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) break; case LAPD_S_RNR: - LOGP(DLLAPD, LOGL_INFO, "RNR received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "RNR received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* 5.5.3.1: Acknowlege all tx frames up the the N(R)-1 */ lapd_acknowledge(lctx); @@ -1312,21 +1337,21 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) LOGP(DLLAPD, LOGL_INFO, "RNR poll " "command and we are not busy, " "so we reply with RR final " - "response\n"); + "response (dl=%p)\n", dl); /* Send RR with F=1 */ lapd_send_rr(lctx, 1, 0); } else { LOGP(DLLAPD, LOGL_INFO, "RNR poll " "command and we are busy, so " "we reply with RNR final " - "response\n"); + "response (dl=%p)\n", dl); /* Send RNR with F=1 */ lapd_send_rnr(lctx, 1, 0); } } else if (dl->state == LAPD_STATE_TIMER_RECOV) { LOGP(DLLAPD, LOGL_INFO, "RNR poll response " "and we in timer recovery state, so " - "we leave that state\n"); + "we leave that state (dl=%p)\n", dl); /* 5.5.7 Clear timer recovery condition */ lapd_dl_newstate(dl, LAPD_STATE_MF_EST); /* V(S) to the N(R) in the RNR frame */ @@ -1334,15 +1359,15 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) } } else LOGP(DLLAPD, LOGL_INFO, "RNR not polling/final state " - "received\n"); + "received (dl=%p)\n", dl); /* Send message, if possible due to acknowledged data */ lapd_send_i(lctx, __LINE__); break; case LAPD_S_REJ: - LOGP(DLLAPD, LOGL_INFO, "REJ received in state %s\n", - lapd_state_names[dl->state]); + LOGP(DLLAPD, LOGL_INFO, "REJ received in state %s (dl=%p)\n", + lapd_state_names[dl->state], dl); /* 5.5.3.1: Acknowlege all tx frames up the the N(R)-1 */ lapd_acknowledge(lctx); @@ -1362,7 +1387,7 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) "state and not in own busy " "condition received, so we " "respond with RR final " - "response\n"); + "response (dl=%p)\n", dl); lapd_send_rr(lctx, 1, 0); /* NOTE: In case of sequence error * condition, the REJ frame has been @@ -1376,21 +1401,24 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) "state and in own busy " "condition received, so we " "respond with RNR final " - "response\n"); + "response (dl=%p)\n", dl); lapd_send_rnr(lctx, 1, 0); } } else LOGP(DLLAPD, LOGL_INFO, "REJ response or not " "polling command not in timer recovery " - "state received\n"); + "state received (dl=%p)\n", dl); /* send MDL ERROR INIDCATION to L3 */ if (lctx->cr == dl->cr.rem2loc.resp && lctx->p_f) { + LOGP(DLLAPD, LOGL_ERROR, + "unsolicited supervisory response! (dl=%p)\n", + dl); mdl_error(MDL_CAUSE_UNSOL_SPRV_RESP, lctx); } } else if (lctx->cr == dl->cr.rem2loc.resp && lctx->p_f) { LOGP(DLLAPD, LOGL_INFO, "REJ poll response in timer " - "recovery state received\n"); + "recovery state received (dl=%p)\n", dl); /* Clear an existing peer receiver busy condition */ dl->peer_busy = 0; /* V(S) and V(A) to the N(R) in the REJ frame */ @@ -1412,7 +1440,7 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) "state and not in own busy " "condition received, so we " "respond with RR final " - "response\n"); + "response (dl=%p)\n", dl); lapd_send_rr(lctx, 1, 0); /* NOTE: In case of sequence error * condition, the REJ frame has been @@ -1426,13 +1454,13 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) "state and in own busy " "condition received, so we " "respond with RNR final " - "response\n"); + "response (dl=%p)\n", dl); lapd_send_rnr(lctx, 1, 0); } } else LOGP(DLLAPD, LOGL_INFO, "REJ response or not " "polling command in timer recovery " - "state received\n"); + "state received (dl=%p)\n", dl); } /* FIXME: 5.5.4.2 2) */ @@ -1443,7 +1471,8 @@ static int lapd_rx_s(struct msgb *msg, struct lapd_msg_ctx *lctx) break; default: /* G.3.1 */ - LOGP(DLLAPD, LOGL_ERROR, "Supervisory frame not allowed.\n"); + LOGP(DLLAPD, LOGL_ERROR, + "Supervisory frame not allowed. (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1461,12 +1490,13 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) int length = lctx->length; int rc; - LOGP(DLLAPD, LOGL_INFO, "I received in state %s on SAPI(%u)\n", - lapd_state_names[dl->state], lctx->sapi); + LOGP(DLLAPD, LOGL_INFO, "I received in state %s on SAPI(%u) (dl=%p)\n", + lapd_state_names[dl->state], lctx->sapi, dl); /* G.2.2 Wrong value of the C/R bit */ if (lctx->cr == dl->cr.rem2loc.resp) { - LOGP(DLLAPD, LOGL_ERROR, "I frame response not allowed\n"); + LOGP(DLLAPD, LOGL_ERROR, + "I frame response not allowed (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_FRM_UNIMPL, lctx); return -EINVAL; @@ -1477,7 +1507,8 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) * to a numerical value L>N201 or L=0, an MDL-ERROR-INDICATION * primitive with cause "I frame with incorrect length" * is sent to the mobile management entity. */ - LOGP(DLLAPD, LOGL_ERROR, "I frame length not allowed\n"); + LOGP(DLLAPD, LOGL_ERROR, + "I frame length not allowed (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_IFRM_INC_LEN, lctx); return -EIO; @@ -1488,7 +1519,8 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) * cause "I frame with incorrect use of M bit" is sent to the * mobile management entity. */ if (lctx->more && length < lctx->n201) { - LOGP(DLLAPD, LOGL_ERROR, "I frame with M bit too short\n"); + LOGP(DLLAPD, LOGL_ERROR, + "I frame with M bit too short (dl=%p)\n", dl); msgb_free(msg); mdl_error(MDL_CAUSE_IFRM_INC_MBITS, lctx); return -EIO; @@ -1503,7 +1535,8 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* fall though */ case LAPD_STATE_SABM_SENT: case LAPD_STATE_DISC_SENT: - LOGP(DLLAPD, LOGL_NOTICE, "I frame ignored in this state\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "I frame ignored in this state (dl=%p)\n", dl); msgb_free(msg); return 0; } @@ -1511,7 +1544,7 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.7.1: N(s) sequence error */ if (ns != dl->v_recv) { LOGP(DLLAPD, LOGL_NOTICE, "N(S) sequence error: N(S)=%u, " - "V(R)=%u\n", ns, dl->v_recv); + "V(R)=%u (dl=%p)\n", ns, dl->v_recv, dl); /* discard data */ msgb_free(msg); if (dl->seq_err_cond != 1) { @@ -1545,7 +1578,8 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* Increment receiver state */ dl->v_recv = inc_mod(dl->v_recv, dl->v_range); - LOGP(DLLAPD, LOGL_INFO, "incrementing V(R) to %u\n", dl->v_recv); + LOGP(DLLAPD, LOGL_INFO, "incrementing V(R) to %u (dl=%p)\n", + dl->v_recv, dl); /* 5.5.3.1: Acknowlege all transmitted frames up the the N(R)-1 */ lapd_acknowledge(lctx); /* V(A) is also set here */ @@ -1554,7 +1588,8 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) if (!dl->own_busy) { /* if the frame carries a complete segment */ if (!lctx->more && !dl->rcv_buffer) { - LOGP(DLLAPD, LOGL_INFO, "message in single I frame\n"); + LOGP(DLLAPD, LOGL_INFO, + "message in single I frame (dl=%p)\n", dl); /* send a DATA INDICATION to L3 */ msgb_trim(msg, length); rc = send_dl_l3(PRIM_DL_DATA, PRIM_OP_INDICATION, lctx, @@ -1563,7 +1598,7 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* create rcv_buffer */ if (!dl->rcv_buffer) { LOGP(DLLAPD, LOGL_INFO, "message in multiple " - "I frames (first message)\n"); + "I frames (first message) (dl=%p)\n", dl); dl->rcv_buffer = lapd_msgb_alloc(dl->maxf, "LAPD RX"); dl->rcv_buffer->l3h = dl->rcv_buffer->data; @@ -1571,7 +1606,7 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* concat. rcv_buffer */ if (msgb_l3len(dl->rcv_buffer) + length > dl->maxf) { LOGP(DLLAPD, LOGL_NOTICE, "Received frame " - "overflow!\n"); + "overflow! (dl=%p)\n", dl); } else { memcpy(msgb_put(dl->rcv_buffer, length), msg->l3h, length); @@ -1579,14 +1614,14 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* if the last segment was received */ if (!lctx->more) { LOGP(DLLAPD, LOGL_INFO, "message in multiple " - "I frames (last message)\n"); + "I frames (last message) (dl=%p)\n", dl); rc = send_dl_l3(PRIM_DL_DATA, PRIM_OP_INDICATION, lctx, dl->rcv_buffer); dl->rcv_buffer = NULL; } else LOGP(DLLAPD, LOGL_INFO, "message in multiple " - "I frames (next message)\n"); + "I frames (next message) (dl=%p)\n", dl); msgb_free(msg); } @@ -1599,11 +1634,13 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) /* 5.5.2.1 */ /* check if we are not in own receiver busy */ if (!dl->own_busy) { - LOGP(DLLAPD, LOGL_INFO, "we are not busy, send RR\n"); + LOGP(DLLAPD, LOGL_INFO, + "we are not busy, send RR (dl=%p)\n", dl); /* Send RR with F=1 */ rc = lapd_send_rr(lctx, 1, 0); } else { - LOGP(DLLAPD, LOGL_INFO, "we are busy, send RNR\n"); + LOGP(DLLAPD, LOGL_INFO, + "we are busy, send RNR (dl=%p)\n", dl); /* Send RNR with F=1 */ rc = lapd_send_rnr(lctx, 1, 0); } @@ -1621,14 +1658,16 @@ static int lapd_rx_i(struct msgb *msg, struct lapd_msg_ctx *lctx) if (rc) { LOGP(DLLAPD, LOGL_INFO, "we are not busy and " - "have no pending data, send RR\n"); + "have no pending data, send RR (dl=%p)\n", + dl); /* Send RR with F=0 */ return lapd_send_rr(lctx, 0, 0); } /* all I or one RR is sent, we are done */ return 0; } else { - LOGP(DLLAPD, LOGL_INFO, "we are busy, send RNR\n"); + LOGP(DLLAPD, LOGL_INFO, + "we are busy, send RNR (dl=%p)\n", dl); /* Send RNR with F=0 */ rc = lapd_send_rnr(lctx, 0, 0); } @@ -1656,7 +1695,8 @@ int lapd_ph_data_ind(struct msgb *msg, struct lapd_msg_ctx *lctx) rc = lapd_rx_i(msg, lctx); break; default: - LOGP(DLLAPD, LOGL_NOTICE, "unknown LAPD format\n"); + LOGP(DLLAPD, LOGL_NOTICE, + "unknown LAPD format (dl=%p)\n", lctx->dl); msgb_free(msg); rc = -EINVAL; } @@ -1695,9 +1735,10 @@ static int lapd_est_req(struct osmo_dlsap_prim *dp, struct lapd_msg_ctx *lctx) if (msg->len) LOGP(DLLAPD, LOGL_INFO, "perform establishment with content " - "(SABM)\n"); + "(SABM) (dl=%p)\n", dl); else - LOGP(DLLAPD, LOGL_INFO, "perform normal establishm. (SABM)\n"); + LOGP(DLLAPD, LOGL_INFO, + "perform normal establishm. (SABM), (dl=%p)\n", dl); /* Flush send-queue */ /* Clear send-buffer */ @@ -1753,13 +1794,14 @@ static int lapd_data_req(struct osmo_dlsap_prim *dp, struct lapd_msg_ctx *lctx) if (msgb_l3len(msg) == 0) { LOGP(DLLAPD, LOGL_ERROR, - "writing an empty message is not possible.\n"); + "writing an empty message is not possible. (dl=%p)\n", dl); msgb_free(msg); return -1; } LOGP(DLLAPD, LOGL_INFO, - "writing message to send-queue: l3len: %d\n", msgb_l3len(msg)); + "writing message to send-queue: l3len: %d (dl=%p)\n", + msgb_l3len(msg), dl); /* Write data into the send queue */ msgb_enqueue(&dl->send_queue, msg); @@ -1782,17 +1824,19 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) struct lapd_msg_ctx nctx; - LOGP(DLLAPD, LOGL_INFO, "%s() called from line %d\n", __func__, line); + LOGP(DLLAPD, LOGL_INFO, + "%s() called from line %d (dl=%p)\n", __func__, line, dl); next_frame: if (dl->peer_busy) { - LOGP(DLLAPD, LOGL_INFO, "peer busy, not sending\n"); + LOGP(DLLAPD, LOGL_INFO, "peer busy, not sending (dl=%p)\n", dl); return rc; } if (dl->state == LAPD_STATE_TIMER_RECOV) { - LOGP(DLLAPD, LOGL_INFO, "timer recovery, not sending\n"); + LOGP(DLLAPD, LOGL_INFO, + "timer recovery, not sending (dl=%p)\n", dl); return rc; } @@ -1804,8 +1848,8 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) * 5.5.7. */ if (dl->v_send == add_mod(dl->v_ack, k, dl->v_range)) { LOGP(DLLAPD, LOGL_INFO, "k frames outstanding, not sending " - "more (k=%u V(S)=%u V(A)=%u)\n", k, dl->v_send, - dl->v_ack); + "more (k=%u V(S)=%u V(A)=%u) (dl=%p)\n", k, dl->v_send, + dl->v_ack, dl); return rc; } @@ -1822,7 +1866,7 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) if (!dl->send_buffer) return rc; LOGP(DLLAPD, LOGL_INFO, "get message from " - "send-queue\n"); + "send-queue (dl=%p)\n", dl); } /* How much is left in the send-buffer? */ @@ -1832,9 +1876,9 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) if (length > lctx->n201) length = lctx->n201; LOGP(DLLAPD, LOGL_INFO, "msg-len %d sent %d left %d N201 %d " - "length %d first byte %02x\n", + "length %d first byte %02x (dl=%p)\n", msgb_l3len(dl->send_buffer), dl->send_out, left, - lctx->n201, length, dl->send_buffer->l3h[0]); + lctx->n201, length, dl->send_buffer->l3h[0], dl); /* If message in send-buffer is completely sent */ if (left == 0) { msgb_free(dl->send_buffer); @@ -1842,8 +1886,8 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) goto next_message; } - LOGP(DLLAPD, LOGL_INFO, "send I frame %sV(S)=%d\n", - (left > length) ? "segment " : "", dl->v_send); + LOGP(DLLAPD, LOGL_INFO, "send I frame %sV(S)=%d (dl=%p)\n", + (left > length) ? "segment " : "", dl->v_send, dl); /* Create I frame (segment) and transmit-buffer content */ msg = lapd_msgb_alloc(length, "LAPD I"); @@ -1876,7 +1920,7 @@ static int lapd_send_i(struct lapd_msg_ctx *lctx, int line) dl->send_out += length; } else { LOGP(DLLAPD, LOGL_INFO, "resend I frame from tx buffer " - "V(S)=%d\n", dl->v_send); + "V(S)=%d (dl=%p)\n", dl->v_send, dl); /* Create I frame (segment) from tx_hist */ length = dl->tx_hist[h].msg->len; @@ -1924,16 +1968,16 @@ static int lapd_susp_req(struct osmo_dlsap_prim *dp, struct lapd_msg_ctx *lctx) struct lapd_datalink *dl = lctx->dl; struct msgb *msg = dp->oph.msg; - LOGP(DLLAPD, LOGL_INFO, "perform suspension\n"); + LOGP(DLLAPD, LOGL_INFO, "perform suspension (dl=%p)\n", dl); /* put back the send-buffer to the send-queue (first position) */ if (dl->send_buffer) { LOGP(DLLAPD, LOGL_INFO, "put frame in sendbuffer back to " - "queue\n"); + "queue (dl=%p)\n", dl); llist_add(&dl->send_buffer->list, &dl->send_queue); dl->send_buffer = NULL; } else - LOGP(DLLAPD, LOGL_INFO, "no frame in |