retronetworking
/
osmo-v5
13
1
Fork 1
Code Issues Pull Requests Projects Releases Wiki Activity

Introduce LOGV5IF, LOGV5LI and LOGV5UP log macros 

This helps us to always log proper context.
This commit is contained in:
Harald Welte 2023-08-13 16:11:08 +02:00 committed by Andreas Eversberg
parent 7709ea0ba2
commit da2b9e1fca
10 changed files with 231 additions and 228 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

22
src/lapv5.c
View File

@ -135,7 +135,7 @@ static struct lapv5_sap *lapv5_sap_alloc(struct lapv5_instance *li, uint16_t v5d
if (!sap) if (!sap)
return NULL; return NULL;
LOGP(DLLAPD, LOGL_DEBUG, "(%s): LAPV5 Allocating SAP for V5_DLADDR=%u (dl=%p, sap=%p)\n", LOGLI(li, LOGL_DEBUG, "(%s): LAPV5 Allocating SAP for V5_DLADDR=%u (dl=%p, sap=%p)\n",
name, v5dladdr, &sap->dl, sap); name, v5dladdr, &sap->dl, sap);
sap->li = li; sap->li = li;
@ -144,7 +144,7 @@ static struct lapv5_sap *lapv5_sap_alloc(struct lapv5_instance *li, uint16_t v5d
profile = &li->profile; profile = &li->profile;
k = profile->k[0]; k = profile->k[0];
LOGP(DLLAPD, LOGL_DEBUG, "(%s): k=%d N200=%d N201=%d T200=%d.%d T203=%d.%d\n", LOGLI(li, LOGL_DEBUG, "(%s): k=%d N200=%d N201=%d T200=%d.%d T203=%d.%d\n",
name, k, profile->n200, profile->n201, profile->t200_sec, name, k, profile->n200, profile->n201, profile->t200_sec,
profile->t200_usec, profile->t203_sec, profile->t203_usec); profile->t200_usec, profile->t203_sec, profile->t203_usec);
lapd_dl_init2(dl, k, 128, profile->n201, name); lapd_dl_init2(dl, k, 128, profile->n201, name);
@ -491,7 +491,7 @@ int lapv5ef_rx(struct v5x_link *link, struct msgb *msg)
msg->l1h = msg->data; msg->l1h = msg->data;
if (msgb_length(msg) < 2) { if (msgb_length(msg) < 2) {
LOGP(DV5EF, LOGL_ERROR, "Frame too short.\n"); LOGV5L(link, DV5EF, LOGL_ERROR, "Frame too short.\n");
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }
@ -503,7 +503,7 @@ int lapv5ef_rx(struct v5x_link *link, struct msgb *msg)
if (!is_isdn) { if (!is_isdn) {
LOGP(DV5EF, LOGL_ERROR, "EFaddr are structured like isdn-type L3 Address.\n"); LOGV5L(link, DV5EF, LOGL_ERROR, "EFaddr are structured like isdn-type L3 Address.\n");
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }
@ -535,30 +535,30 @@ int lapv5ef_rx(struct v5x_link *link, struct msgb *msg)
default: default:
if (efaddr >= 8176) { if (efaddr >= 8176) {
/* reserved as per Section 9.2.2.2 of G.964 */ /* reserved as per Section 9.2.2.2 of G.964 */
LOGP(DV5EF, LOGL_ERROR, "No LAPV5 protocol for EFaddr %d.\n", efaddr); LOGV5L(link, DV5EF, LOGL_ERROR, "No LAPV5 protocol for EFaddr %d.\n", efaddr);
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }
/* relay function for LAPD of user ports */ /* relay function for LAPD of user ports */
v5up = v5x_user_port_find(link->interface, efaddr, true); v5up = v5x_user_port_find(link->interface, efaddr, true);
if (!v5up) { if (!v5up) {
LOGP(DV5EF, LOGL_ERROR, "No ISDN user port instance for EFaddr %d created.\n", efaddr); LOGV5L(link, DV5EF, LOGL_ERROR, "No ISDN user port instance for EFaddr %d created.\n", efaddr);
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }
if (!v5x_le_port_isdn_is_operational(v5up->port_fi)) { if (!v5x_le_port_isdn_is_operational(v5up->port_fi)) {
LOGP(DV5EF, LOGL_NOTICE, "Dropping D-channel (AN->LE) message of non-operational ISDN port for EFaddr %d.\n", efaddr); LOGV5UP(v5up, DV5EF, LOGL_NOTICE, "Dropping D-channel (AN->LE) message of non-operational ISDN port for EFaddr %d.\n", efaddr);
msgb_free(msg); msgb_free(msg);
return -EIO; return -EIO;
} }
LOGP(DV5EF, LOGL_DEBUG, "Recevied frame for EFaddr %d: %s\n", efaddr, osmo_hexdump(msg->data, msg->len)); LOGV5UP(v5up, DV5EF, LOGL_DEBUG, "Recevied frame for EFaddr %d: %s\n", efaddr, osmo_hexdump(msg->data, msg->len));
ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_DATA_IND, msg->data, msg->len); ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_DATA_IND, msg->data, msg->len);
msgb_free(msg); msgb_free(msg);
return 0; return 0;
} }
if (!li) { if (!li) {
LOGP(DV5EF, LOGL_ERROR, "No LAPV5 instance for EFaddr %d created.\n", efaddr); LOGV5UP(v5up, DV5EF, LOGL_ERROR, "No LAPV5 instance for EFaddr %d created.\n", efaddr);
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }
@ -573,12 +573,12 @@ int lapv5ef_tx(struct v5x_user_port *v5up, struct msgb *msg)
uint16_t efaddr = v5up->nr, efaddr_enc; uint16_t efaddr = v5up->nr, efaddr_enc;
if (!v5x_le_port_isdn_is_operational(v5up->port_fi)) { if (!v5x_le_port_isdn_is_operational(v5up->port_fi)) {
LOGP(DV5EF, LOGL_NOTICE, "Dropping D-channel (LE->AN) message of non-operational ISDN port for EFaddr %d.\n", efaddr); LOGV5UP(v5up, DV5EF, LOGL_NOTICE, "Dropping D-channel (LE->AN) message of non-operational ISDN port for EFaddr %d.\n", efaddr);
msgb_free(msg); msgb_free(msg);
return -EIO; return -EIO;
} }
/* relay function for LAPD of user ports */ /* relay function for LAPD of user ports */
LOGP(DV5EF, LOGL_DEBUG, "Sending frame for EFaddr %d: %s\n", efaddr, osmo_hexdump(msg->data, msg->len)); LOGV5UP(v5up, DV5EF, LOGL_DEBUG, "Sending frame for EFaddr %d: %s\n", efaddr, osmo_hexdump(msg->data, msg->len));
msg->l2h = msgb_push(msg, 2); msg->l2h = msgb_push(msg, 2);
efaddr_enc = v5x_l3_addr_enc(efaddr, 1); efaddr_enc = v5x_l3_addr_enc(efaddr, 1);
msg->l2h[0] = efaddr_enc >> 8; msg->l2h[0] = efaddr_enc >> 8;

2
src/v52_le_bcc_fsm.c
View File

@ -653,7 +653,7 @@ static struct v52_bcc_proc *v52_le_bcc_create(struct v5x_interface *v5if, uint16
OSMO_ASSERT(v5if); OSMO_ASSERT(v5if);
LOGP(DV5BCC, LOGL_DEBUG, "Creating BCC instance, initiated by %s.\n", (source_id) ? "AN" : "LE"); LOGV5IF(v5if, DV5BCC, LOGL_DEBUG, "Creating BCC instance, initiated by %s.\n", (source_id) ? "AN" : "LE");
bcc = talloc_zero(v5if, struct v52_bcc_proc); bcc = talloc_zero(v5if, struct v52_bcc_proc);
if (!bcc) if (!bcc)

4
src/v52_le_pp_fsm.c
View File

@ -740,7 +740,7 @@ int v52_le_pp_dl_rcv(struct v5x_link *v5l, uint16_t cc_id, uint8_t msg_type, con
int check_sn = 0; int check_sn = 0;
if (!pp) { if (!pp) {
LOGP(DV5PP, LOGL_NOTICE, "Received message from DL, but there is no protection on this interface.\n"); LOGV5L(v5l, DV5PP, LOGL_NOTICE, "Received message from DL, but there is no protection on this interface.\n");
return -EIO; return -EIO;
} }
@ -817,7 +817,7 @@ int v52_le_pp_mdu_snd(struct v5x_interface *v5if, enum v5x_mgmt_prim prim, uint8
struct v52_pp_mgmt_info info = { link_id, ts, cause }; struct v52_pp_mgmt_info info = { link_id, ts, cause };
if (!v5if->protection.pp) { if (!v5if->protection.pp) {
LOGP(DV5PP, LOGL_NOTICE, "Cannot perform action, because there is no protection on this interface.\n"); LOGV5IF(v5if, DV5PP, LOGL_NOTICE, "Cannot perform action, because there is no protection on this interface.\n");
return -EINVAL; return -EINVAL;
} }
OSMO_ASSERT(v5if->protection.pp); OSMO_ASSERT(v5if->protection.pp);

38
src/v5x_data.c
View File

@ -92,7 +92,7 @@ struct v5x_link *v5x_link_create(struct v5x_interface *v5if, uint8_t id)
int rc; int rc;
if (v5x_link_find_id(v5if, id)) { if (v5x_link_find_id(v5if, id)) {
LOGP(DV5, LOGL_ERROR, "Link %d already exists.\n", id); LOGV5IF(v5if, DV5, LOGL_ERROR, "Link %d already exists.\n", id);
return NULL; return NULL;
} }
@ -175,11 +175,11 @@ int v5x_link_destroy(struct v5x_link *v5l)
count = v5x_link_count(v5l->interface); count = v5x_link_count(v5l->interface);
if (count > 1 && v5l->interface->primary_link == v5l) { if (count > 1 && v5l->interface->primary_link == v5l) {
LOGP(DV5, LOGL_ERROR, "Link %d is primary. Cannot remove it, while other links exist.\n", v5l->id); LOGV5L(v5l, DV5, LOGL_ERROR, "Link is primary. Cannot remove it, while other links exist.\n");
return -EINVAL; return -EINVAL;
} }
if (count > 2 && v5l->interface->secondary_link == v5l) { if (count > 2 && v5l->interface->secondary_link == v5l) {
LOGP(DV5, LOGL_ERROR, "Link %d is secondary (standby). Cannot remove it, while other (not primary) links exist.\n", v5l->id); LOGV5L(v5l, DV5, LOGL_ERROR, "Link is secondary (standby). Cannot remove it, while other (not primary) links exist.\n");
return -EINVAL; return -EINVAL;
} }
@ -355,7 +355,7 @@ struct v5x_user_port *v5x_user_port_create(struct v5x_interface *v5if, uint16_t
int rc; int rc;
if (v5x_user_port_find(v5if, nr, (type == V5X_USER_TYPE_ISDN))) { if (v5x_user_port_find(v5if, nr, (type == V5X_USER_TYPE_ISDN))) {
LOGP(DV5, LOGL_ERROR, "User port %d already exists.\n", nr); LOGV5IF(v5if, DV5, LOGL_ERROR, "User port %d already exists.\n", nr);
return NULL; return NULL;
} }
@ -364,21 +364,21 @@ struct v5x_user_port *v5x_user_port_create(struct v5x_interface *v5if, uint16_t
v5l = llist_first_entry(&v5if->links, struct v5x_link, list); v5l = llist_first_entry(&v5if->links, struct v5x_link, list);
if (!v5l->ts[ts1].b_channel) { if (!v5l->ts[ts1].b_channel) {
LOGP(DV5, LOGL_ERROR, "Time slot %d is not a B-channel, select a different one.\n", ts1); LOGV5IF(v5if, DV5, LOGL_ERROR, "Time slot %d is not a B-channel, select a different one.\n", ts1);
return NULL; return NULL;
} }
if ((v5up = v5l->ts[ts1].v5up)) { if ((v5up = v5l->ts[ts1].v5up)) {
LOGP(DV5, LOGL_ERROR, "Time slot %d is already assigned to another user port.\n", ts1); LOGV5IF(v5if, DV5, LOGL_ERROR, "Time slot %d is already assigned to another user port.\n", ts1);
return NULL; return NULL;
} }
if (type == V5X_USER_TYPE_ISDN) { if (type == V5X_USER_TYPE_ISDN) {
if (!v5l->ts[ts2].b_channel) { if (!v5l->ts[ts2].b_channel) {
LOGP(DV5, LOGL_ERROR, "Time slot %d is not a B-channel, select a different one.\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Time slot %d is not a B-channel, select a different one.\n",
ts2); ts2);
return NULL; return NULL;
} }
if ((v5up = v5l->ts[ts2].v5up)) { if ((v5up = v5l->ts[ts2].v5up)) {
LOGP(DV5, LOGL_ERROR, "Time slot %d is already assigned to another user port.\n", ts2); LOGV5IF(v5if, DV5, LOGL_ERROR, "Time slot %d is already assigned to another user port.\n", ts2);
return NULL; return NULL;
} }
} }
@ -411,33 +411,33 @@ struct v5x_user_port *v5x_user_port_create(struct v5x_interface *v5if, uint16_t
v5up->ctrl = v5x_le_ctrl_create(V5X_CTRL_TYPE_PORT, v5up, v5up, nr); v5up->ctrl = v5x_le_ctrl_create(V5X_CTRL_TYPE_PORT, v5up, v5up, nr);
if (!v5up->ctrl) { if (!v5up->ctrl) {
LOGP(DV5, LOGL_ERROR, "Failed to create control protocol\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create control protocol\n");
goto error; goto error;
} }
switch (type) { switch (type) {
case V5X_USER_TYPE_ISDN: case V5X_USER_TYPE_ISDN:
LOGP(DV5, LOGL_NOTICE, "Creating V5 ISDN user port with L3 addr %d\n", nr); LOGV5UP(v5up, DV5, LOGL_NOTICE, "Creating V5 ISDN user port with L3 addr %d\n", nr);
sprintf(v5up->ifname, "%d-isdn-%d", v5if->id, nr); sprintf(v5up->ifname, "%d-isdn-%d", v5if->id, nr);
OSMO_ASSERT(nr <= 8175); OSMO_ASSERT(nr <= 8175);
v5up->port_fi = v5x_le_port_isdn_create(v5up, nr); v5up->port_fi = v5x_le_port_isdn_create(v5up, nr);
if (!v5up->port_fi) { if (!v5up->port_fi) {
LOGP(DV5, LOGL_ERROR, "Failed to create port control\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create port control\n");
goto error; goto error;
} }
break; break;
case V5X_USER_TYPE_PSTN: case V5X_USER_TYPE_PSTN:
LOGP(DV5, LOGL_NOTICE, "Creating V5 PSTN user port with L3 addr %d\n", nr); LOGV5UP(v5up, DV5, LOGL_NOTICE, "Creating V5 PSTN user port with L3 addr %d\n", nr);
sprintf(v5up->ifname, "%d-pstn-%d", v5if->id, nr); sprintf(v5up->ifname, "%d-pstn-%d", v5if->id, nr);
OSMO_ASSERT(nr <= 32767); OSMO_ASSERT(nr <= 32767);
v5up->port_fi = v5x_le_port_pstn_create(v5up, nr); v5up->port_fi = v5x_le_port_pstn_create(v5up, nr);
if (!v5up->port_fi) { if (!v5up->port_fi) {
LOGP(DV5, LOGL_ERROR, "Failed to create port control\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create port control\n");
goto error; goto error;
} }
v5up->pstn.proto = v5x_le_pstn_create(v5up, nr); v5up->pstn.proto = v5x_le_pstn_create(v5up, nr);
if (!v5up->pstn.proto) { if (!v5up->pstn.proto) {
LOGP(DV5, LOGL_ERROR, "Failed to create PSTN protocol\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create PSTN protocol\n");
goto error; goto error;
} }
/* bring port into service */ /* bring port into service */
@ -450,17 +450,17 @@ struct v5x_user_port *v5x_user_port_create(struct v5x_interface *v5if, uint16_t
/* EC needs to adapt, NLP causes better results on quick volume changes */ /* EC needs to adapt, NLP causes better results on quick volume changes */
v5up->ep[i].ec = echo_can_create(EC_TAPS, ECHO_CAN_USE_ADAPTION | ECHO_CAN_USE_NLP); v5up->ep[i].ec = echo_can_create(EC_TAPS, ECHO_CAN_USE_ADAPTION | ECHO_CAN_USE_NLP);
if (!v5up->ep[i].ec) { if (!v5up->ep[i].ec) {
LOGP(DV5, LOGL_ERROR, "Failed to create line echo canceler\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create line echo canceler\n");
goto error; goto error;
} }
v5up->ep[i].es = echo_sup_create(v5up, 8000); v5up->ep[i].es = echo_sup_create(v5up, 8000);
if (!v5up->ep[i].es) { if (!v5up->ep[i].es) {
LOGP(DV5, LOGL_ERROR, "Failed to create line echo suppressor\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create line echo suppressor\n");
goto error; goto error;
} }
rc = answertone_init(&v5up->ep[i].at, 8000); rc = answertone_init(&v5up->ep[i].at, 8000);
if (rc < 0) { if (rc < 0) {
LOGP(DV5, LOGL_ERROR, "Failed to create answer tone detector\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create answer tone detector\n");
goto error; goto error;
} }
if (type != V5X_USER_TYPE_ISDN) if (type != V5X_USER_TYPE_ISDN)
@ -469,7 +469,7 @@ struct v5x_user_port *v5x_user_port_create(struct v5x_interface *v5if, uint16_t
rc = ph_socket_init(&v5up->ph_socket, ph_socket_rx_cb, v5up, v5up->ifname, 1); rc = ph_socket_init(&v5up->ph_socket, ph_socket_rx_cb, v5up, v5up->ifname, 1);
if (rc < 0) { if (rc < 0) {
LOGP(DV5, LOGL_ERROR, "Failed to create PH-socket\n"); LOGV5UP(v5up, DV5, LOGL_ERROR, "Failed to create PH-socket\n");
goto error; goto error;
} }
@ -488,7 +488,7 @@ void v5x_user_port_destroy(struct v5x_user_port *v5up)
{ {
int i; int i;
LOGP(DV5, LOGL_NOTICE, "Destroying V5 user port with L3 addr %d\n", v5up->nr); LOGV5UP(v5up, DV5, LOGL_NOTICE, "Destroying V5 user port with L3 addr %d\n", v5up->nr);
/* close first, because it sends messages */ /* close first, because it sends messages */
ph_socket_exit(&v5up->ph_socket); ph_socket_exit(&v5up->ph_socket);

9
src/v5x_internal.h
View File

@ -37,6 +37,15 @@
#include "libecho/answertone.h" #include "libecho/answertone.h"
#include "ph_socket.h" #include "ph_socket.h"
#define LOGV5IF(v5i, ss, level, fmt, args ...) \
LOGP(ss, level, "(%s): " fmt, v5x_interface_name(v5i), ## args)
#define LOGV5L(v5l, ss, level, fmt, args ...) \
LOGP(ss, level, "(%s-L%u): " fmt, v5x_interface_name((v5l)->interface), (v5l)->id, ## args)
#define LOGV5UP(v5up, ss, level, fmt, args ...) \
LOGP(ss, level, "(%s-P%u): " fmt, v5x_interface_name((v5up)->interface), (v5up)->nr, ## args)
/* Table 35/G.964 */ /* Table 35/G.964 */
enum v5x_mph_prim { enum v5x_mph_prim {
MPH_UBR, /* Unblock (req) */ MPH_UBR, /* Unblock (req) */

20
src/v5x_l1_fsm.c
View File

@ -637,42 +637,42 @@ int v5x_l1_signal_rcv(struct v5x_link *v5l, enum l1_signal_prim prim)
switch (prim) { switch (prim) {
case L1_SIGNAL_LOS: case L1_SIGNAL_LOS:
LOGP(DV5L1, LOGL_DEBUG, "Signal LOS detected on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal LOS detected on link %d of interface %d.\n", v5l->id, v5if->id);
if (!l1->los) { if (!l1->los) {
l1->los = 1; l1->los = 1;
osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_LOS, NULL); osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_LOS, NULL);
} }
break; break;
case L1_SIGNAL_NO_LOS: case L1_SIGNAL_NO_LOS:
LOGP(DV5L1, LOGL_DEBUG, "Signal LOS gone on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal LOS gone on link %d of interface %d.\n", v5l->id, v5if->id);
if (l1->los) { if (l1->los) {
l1->los = 0; l1->los = 0;
state_changed = 1; state_changed = 1;
} }
break; break;
case L1_SIGNAL_RAI: case L1_SIGNAL_RAI:
LOGP(DV5L1, LOGL_DEBUG, "Signal RAI detected on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal RAI detected on link %d of interface %d.\n", v5l->id, v5if->id);
if (!l1->rai) { if (!l1->rai) {
l1->rai = 1; l1->rai = 1;
osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_RAI, NULL); osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_RAI, NULL);
} }
break; break;
case L1_SIGNAL_NO_RAI: case L1_SIGNAL_NO_RAI:
LOGP(DV5L1, LOGL_DEBUG, "Signal RAI gone on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal RAI gone on link %d of interface %d.\n", v5l->id, v5if->id);
if (l1->rai) { if (l1->rai) {
l1->rai = 0; l1->rai = 0;
state_changed = 1; state_changed = 1;
} }
break; break;
case L1_SIGNAL_AIS: case L1_SIGNAL_AIS:
LOGP(DV5L1, LOGL_DEBUG, "Signal AIS detected on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal AIS detected on link %d of interface %d.\n", v5l->id, v5if->id);
if (!l1->ais) { if (!l1->ais) {
l1->ais = 1; l1->ais = 1;
osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_AIS, NULL); osmo_fsm_inst_dispatch(fi, V5X_L1FSM_E_AIS, NULL);
} }
break; break;
case L1_SIGNAL_NO_AIS: case L1_SIGNAL_NO_AIS:
LOGP(DV5L1, LOGL_DEBUG, "Signal AIS gone on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Signal AIS gone on link %d of interface %d.\n", v5l->id, v5if->id);
if (l1->ais) { if (l1->ais) {
l1->ais = 0; l1->ais = 0;
state_changed = 1; state_changed = 1;
@ -681,20 +681,20 @@ int v5x_l1_signal_rcv(struct v5x_link *v5l, enum l1_signal_prim prim)
case L1_SIGNAL_SA7_0: case L1_SIGNAL_SA7_0:
if (l1->sa7 != 0) { if (l1->sa7 != 0) {
LOGP(DV5L1, LOGL_DEBUG, "Bit Sa7=0 on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Bit Sa7=0 on link %d of interface %d.\n", v5l->id, v5if->id);
l1->sa7 = 0; l1->sa7 = 0;
state_changed = 1; state_changed = 1;
} }
break; break;
case L1_SIGNAL_SA7_1: case L1_SIGNAL_SA7_1:
if (l1->sa7 != 1) { if (l1->sa7 != 1) {
LOGP(DV5L1, LOGL_DEBUG, "Bit Sa7=1 on link %d of interface %d.\n", v5l->id, v5if->id); LOGV5L(v5l, DV5L1, LOGL_DEBUG, "Bit Sa7=1 on link %d of interface %d.\n", v5l->id, v5if->id);
l1->sa7 = 1; l1->sa7 = 1;
state_changed = 1; state_changed = 1;
} }
break; break;
default: default:
LOGP(DV5L1, LOGL_NOTICE, "Invalid L1 primitive %d receied from physical layer.\n", prim); LOGV5L(v5l, DV5L1, LOGL_NOTICE, "Invalid L1 primitive %d receied from physical layer.\n", prim);
return -EINVAL; return -EINVAL;
} }
@ -734,7 +734,7 @@ void v5x_l1_mph_snd(struct v5x_link *v5l, enum v5x_mph_prim prim)
// FIXME: do we need this? // FIXME: do we need this?
break; break;
default: default:
LOGP(DV5PORT, LOGL_NOTICE, "Got invalid prim %d at this protocol\n", prim); LOGV5L(v5l, DV5PORT, LOGL_NOTICE, "Got invalid prim %d at this protocol\n", prim);
return; return;
} }

14
src/v5x_le_ctrl_fsm.c
View File

@ -650,8 +650,8 @@ int v5x_le_ctrl_dl_rcv(struct v5x_interface *v5if, uint16_t l3_addr, bool is_isd
case V5X_CTRL_MSGT_PORT_CTRL_ACK: case V5X_CTRL_MSGT_PORT_CTRL_ACK:
v5up = v5x_user_port_find(v5if, l3_addr, is_isdn); v5up = v5x_user_port_find(v5if, l3_addr, is_isdn);
if (!v5up) { if (!v5up) {
LOGP(DV5CTRL, LOGL_ERROR, "Received %s port control message with unknown layer 3 address %d. " LOGV5IF(v5if, DV5CTRL, LOGL_ERROR, "Received %s port control message with unknown layer 3 address %d. "
"Please check provisioning!\n", is_isdn ? "ISDN" : "PSTN", l3_addr); "Please check provisioning!\n", is_isdn ? "ISDN" : "PSTN", l3_addr);
return -ENODEV; return -ENODEV;
} }
return v5x_rcv_ctrl_port(v5up, msg_type, tp); return v5x_rcv_ctrl_port(v5up, msg_type, tp);
@ -664,8 +664,8 @@ int v5x_le_ctrl_dl_rcv(struct v5x_interface *v5if, uint16_t l3_addr, bool is_isd
case V52_CTRL_MSGT_LCP_LINK_CTRL_ACK: case V52_CTRL_MSGT_LCP_LINK_CTRL_ACK:
v5l = v5x_link_find_id(v5if, l3_addr); v5l = v5x_link_find_id(v5if, l3_addr);
if (!v5l) { if (!v5l) {
LOGP(DV5CTRL, LOGL_ERROR, "Received link control message with unknown link ID %d. Please " LOGV5IF(v5if, DV5CTRL, LOGL_ERROR, "Received link control message with unknown link ID %d. Please "
"check provisioning!\n", l3_addr); "check provisioning!\n", l3_addr);
return -ENODEV; return -ENODEV;
} }
return v52_rcv_ctrl_link(v5l, msg_type, tp); return v52_rcv_ctrl_link(v5l, msg_type, tp);
@ -682,7 +682,7 @@ int v5x_le_ctrl_dl_rcv(struct v5x_interface *v5if, uint16_t l3_addr, bool is_isd
int v5x_le_ctrl_common_snd(struct v5x_interface *v5if, enum v5x_ctrl_func_id cfi, int v5x_le_ctrl_common_snd(struct v5x_interface *v5if, enum v5x_ctrl_func_id cfi,
uint8_t *rej_cause, uint8_t *variant, uint32_t *interface_id) uint8_t *rej_cause, uint8_t *variant, uint32_t *interface_id)
{ {
LOGP(DV5CTRL, LOGL_DEBUG, "Sending MDU-CTRL (from common control).\n"); LOGV5IF(v5if, DV5CTRL, LOGL_DEBUG, "Sending MDU-CTRL (from common control).\n");
osmo_fsm_inst_dispatch(v5if->control.ctrl->fi, V5X_CTRL_EV_MDU_CTRL, osmo_fsm_inst_dispatch(v5if->control.ctrl->fi, V5X_CTRL_EV_MDU_CTRL,
v5x_enc_ctrl_common(cfi, variant, rej_cause, interface_id)); v5x_enc_ctrl_common(cfi, variant, rej_cause, interface_id));
@ -692,7 +692,7 @@ int v5x_le_ctrl_common_snd(struct v5x_interface *v5if, enum v5x_ctrl_func_id cfi
/* send port message from upper layer */ /* send port message from upper layer */
int v5x_le_ctrl_port_snd(struct v5x_user_port *v5up, enum v5x_ctrl_func_el cfe) int v5x_le_ctrl_port_snd(struct v5x_user_port *v5up, enum v5x_ctrl_func_el cfe)
{ {
LOGP(DV5CTRL, LOGL_DEBUG, "Sending FE (from port).\n"); LOGV5UP(v5up, DV5CTRL, LOGL_DEBUG, "Sending FE (from port).\n");
osmo_fsm_inst_dispatch(v5up->ctrl->fi, V5X_CTRL_EV_MDU_CTRL, osmo_fsm_inst_dispatch(v5up->ctrl->fi, V5X_CTRL_EV_MDU_CTRL,
v5x_enc_ctrl_port(v5up, cfe, v5up->type == V5X_USER_TYPE_ISDN)); v5x_enc_ctrl_port(v5up, cfe, v5up->type == V5X_USER_TYPE_ISDN));
@ -702,7 +702,7 @@ int v5x_le_ctrl_port_snd(struct v5x_user_port *v5up, enum v5x_ctrl_func_el cfe)
/* send link message from upper layer */ /* send link message from upper layer */
int v52_le_ctrl_link_snd(struct v5x_link *v5l, enum v52_link_ctrl_func lcf) int v52_le_ctrl_link_snd(struct v5x_link *v5l, enum v52_link_ctrl_func lcf)
{ {
LOGP(DV5CTRL, LOGL_DEBUG, "Sending FE (from LCP).\n"); LOGV5L(v5l, DV5CTRL, LOGL_DEBUG, "Sending FE (from LCP).\n");
osmo_fsm_inst_dispatch(v5l->ctrl->fi, V5X_CTRL_EV_MDU_CTRL, osmo_fsm_inst_dispatch(v5l->ctrl->fi, V5X_CTRL_EV_MDU_CTRL,
v52_enc_ctrl_link(v5l, lcf)); v52_enc_ctrl_link(v5l, lcf));

318
src/v5x_le_management.c
View File

@ -101,15 +101,15 @@ static void block_all_ports(struct v5x_interface *v5if, bool silently, bool isdn
struct v5x_user_port *v5up; struct v5x_user_port *v5up;
bool any = false; bool any = false;
LOGP(DV5MGMT, LOGL_INFO, "%slocking %s%s%s ports:\n", (silently) ? "Silently b" : "B", LOGV5IF(v5if,DV5MGMT, LOGL_INFO, "%slocking %s%s%s ports:\n", (silently) ? "Silently b" : "B",
(isdn) ? "ISDN" : "", (isdn && pstn) ? "+" : "", (pstn) ? "PSTN" : ""); (isdn) ? "ISDN" : "", (isdn && pstn) ? "+" : "", (pstn) ? "PSTN" : "");
llist_for_each_entry(v5up, &v5if->user_ports, list) { llist_for_each_entry(v5up, &v5if->user_ports, list) {
if (!isdn && !v5up->pstn.proto) if (!isdn && !v5up->pstn.proto)
continue; continue;
if (!pstn && v5up->pstn.proto) if (!pstn && v5up->pstn.proto)
continue; continue;
LOGP(DV5MGMT, LOGL_INFO, " -> Set %s port %d into blocked state.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Set %s port into blocked state.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
any = true; any = true;
if (silently) if (silently)
block_unblock_socket(v5up, true); block_unblock_socket(v5up, true);
@ -118,7 +118,7 @@ static void block_all_ports(struct v5x_interface *v5if, bool silently, bool isdn
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
if (silently) if (silently)
v5x_le_port_pstn_block(v5up->port_fi); v5x_le_port_pstn_block(v5up->port_fi);
LOGP(DV5MGMT, LOGL_DEBUG, " -> Send port blocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, " -> Send port blocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked);
} else { } else {
if (silently) if (silently)
@ -127,7 +127,7 @@ static void block_all_ports(struct v5x_interface *v5if, bool silently, bool isdn
} }
if (!any) if (!any)
LOGP(DV5MGMT, LOGL_INFO, " -> Not any port to block.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, " -> Not any port to block.\n");
} }
/* (silently) unblock all ports */ /* (silently) unblock all ports */
@ -136,7 +136,7 @@ static void unblock_all_ports(struct v5x_interface *v5if, bool silently, bool is
struct v5x_user_port *v5up; struct v5x_user_port *v5up;
bool any = false; bool any = false;
LOGP(DV5MGMT, LOGL_INFO, "%snblocking %s%s%s ports:\n", (silently) ? "Silently u" : "U", LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "%snblocking %s%s%s ports:\n", (silently) ? "Silently u" : "U",
(isdn) ? "ISDN" : "", (isdn && pstn) ? "+" : "", (pstn) ? "PSTN" : ""); (isdn) ? "ISDN" : "", (isdn && pstn) ? "+" : "", (pstn) ? "PSTN" : "");
llist_for_each_entry(v5up, &v5if->user_ports, list) { llist_for_each_entry(v5up, &v5if->user_ports, list) {
if (!v5up->le_unblocked) if (!v5up->le_unblocked)
@ -145,8 +145,8 @@ static void unblock_all_ports(struct v5x_interface *v5if, bool silently, bool is
continue; continue;
if (!pstn && v5up->pstn.proto) if (!pstn && v5up->pstn.proto)
continue; continue;
LOGP(DV5MGMT, LOGL_INFO, " -> Set %s port %d into unblocked state.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Set %s port into unblocked state.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
any = true; any = true;
if (silently) if (silently)
block_unblock_socket(v5up, false); block_unblock_socket(v5up, false);
@ -155,7 +155,7 @@ static void unblock_all_ports(struct v5x_interface *v5if, bool silently, bool is
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
if (silently) if (silently)
v5x_le_port_pstn_unblock(v5up->port_fi); v5x_le_port_pstn_unblock(v5up->port_fi);
LOGP(DV5MGMT, LOGL_DEBUG, " -> Send port unblocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, " -> Send port unblocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked);
} else { } else {
if (silently) if (silently)
@ -164,7 +164,7 @@ static void unblock_all_ports(struct v5x_interface *v5if, bool silently, bool is
} }
if (!any) if (!any)
LOGP(DV5MGMT, LOGL_INFO, " -> Not any port to unblock.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, " -> Not any port to unblock.\n");
} }
/* align all ports */ /* align all ports */
@ -173,33 +173,31 @@ static void align_all_ports(struct v5x_interface *v5if)
struct v5x_user_port *v5up; struct v5x_user_port *v5up;
bool any = false; bool any = false;
LOGP(DV5MGMT, LOGL_INFO, "Aligning all ports:\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Aligning all ports:\n");
llist_for_each_entry(v5up, &v5if->user_ports, list) { llist_for_each_entry(v5up, &v5if->user_ports, list) {
if (v5up->le_unblocked) { if (v5up->le_unblocked) {
LOGP(DV5MGMT, LOGL_INFO, " -> Set %s port %d into unblocked state.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Set %s port into unblocked state.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
any = true; any = true;
v5x_port_mph_snd(v5up, MPH_UBR); v5x_port_mph_snd(v5up, MPH_UBR);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, " -> Send port unblocked control to PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, " -> Send port unblocked control to PSTN port.\n");
v5up->nr);
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked);
} }
} else { } else {
LOGP(DV5MGMT, LOGL_INFO, " -> Set %s port %d into blocked state.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Set %s port into blocked state.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
any = true; any = true;
v5x_port_mph_snd(v5up, MPH_BI); v5x_port_mph_snd(v5up, MPH_BI);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, " -> Send port blocked control to PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, " -> Send port blocked control to PSTN port.\n");
v5up->nr);
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked);
} }
} }
} }
if (!any) if (!any)
LOGP(DV5MGMT, LOGL_INFO, " -> Not any port to align.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, " -> Not any port to align.\n");
} }
/***********************************************************************/ /***********************************************************************/
@ -329,172 +327,172 @@ static const struct value_string v5x_le_unblk_all_fsm_event_names[] = {
static void start_timer_system(struct v5x_mgmt_proto *mgmt, int delay) static void start_timer_system(struct v5x_mgmt_proto *mgmt, int delay)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer for system startup delay.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer for system startup delay.\n");
osmo_timer_schedule(&mgmt->timer_system, delay, 0); osmo_timer_schedule(&mgmt->timer_system, delay, 0);
} }
static void start_timer_tr1(struct v5x_mgmt_proto *mgmt) static void start_timer_tr1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TR1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TR1.\n");
osmo_timer_schedule(&mgmt->timer_tr1, 100, 0); osmo_timer_schedule(&mgmt->timer_tr1, 100, 0);
} }
static void start_timer_tr2(struct v5x_mgmt_proto *mgmt) static void start_timer_tr2(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TR2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TR2.\n");
osmo_timer_schedule(&mgmt->timer_tr2, 120, 0); osmo_timer_schedule(&mgmt->timer_tr2, 120, 0);
} }
static void start_timer_tc1(struct v5x_mgmt_proto *mgmt) static void start_timer_tc1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TC1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TC1.\n");
osmo_timer_schedule(&mgmt->timer_tc1, 15, 0); osmo_timer_schedule(&mgmt->timer_tc1, 15, 0);
} }
static void start_timer_tc2(struct v5x_mgmt_proto *mgmt) static void start_timer_tc2(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TC2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TC2.\n");
osmo_timer_schedule(&mgmt->timer_tc2, 60, 0); osmo_timer_schedule(&mgmt->timer_tc2, 60, 0);
} }
static void start_timer_tc3(struct v5x_mgmt_proto *mgmt) static void start_timer_tc3(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TC3.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TC3.\n");
osmo_timer_schedule(&mgmt->timer_tc3, 15, 0); osmo_timer_schedule(&mgmt->timer_tc3, 15, 0);
} }
static void start_timer_tc8(struct v5x_mgmt_proto *mgmt) static void start_timer_tc8(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TC8.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TC8.\n");
osmo_timer_schedule(&mgmt->timer_tc8, 20, 0); osmo_timer_schedule(&mgmt->timer_tc8, 20, 0);
} }
static void start_timer_tc9(struct v5x_mgmt_proto *mgmt) static void start_timer_tc9(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TC9.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TC9.\n");
osmo_timer_schedule(&mgmt->timer_tc9, 95, 0); osmo_timer_schedule(&mgmt->timer_tc9, 95, 0);
} }
static void start_timer_tv1(struct v5x_mgmt_proto *mgmt) static void start_timer_tv1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Start timer TV1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Start timer TV1.\n");
osmo_timer_schedule(&mgmt->timer_tv1, 15, 0); osmo_timer_schedule(&mgmt->timer_tv1, 15, 0);
} }
static void stop_timer_system(struct v5x_mgmt_proto *mgmt) static void stop_timer_system(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer for system startup delay.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer for system startup delay.\n");
osmo_timer_del(&mgmt->timer_system); osmo_timer_del(&mgmt->timer_system);
} }
static void stop_timer_tr1(struct v5x_mgmt_proto *mgmt) static void stop_timer_tr1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TR1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TR1.\n");
osmo_timer_del(&mgmt->timer_tr1); osmo_timer_del(&mgmt->timer_tr1);
} }
static void stop_timer_tr2(struct v5x_mgmt_proto *mgmt) static void stop_timer_tr2(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TR2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TR2.\n");
osmo_timer_del(&mgmt->timer_tr2); osmo_timer_del(&mgmt->timer_tr2);
} }
static void stop_timer_tc1(struct v5x_mgmt_proto *mgmt) static void stop_timer_tc1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TC1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TC1.\n");
osmo_timer_del(&mgmt->timer_tc1); osmo_timer_del(&mgmt->timer_tc1);
} }
static void stop_timer_tc2(struct v5x_mgmt_proto *mgmt) static void stop_timer_tc2(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TC2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TC2.\n");
osmo_timer_del(&mgmt->timer_tc2); osmo_timer_del(&mgmt->timer_tc2);
} }
static void stop_timer_tc3(struct v5x_mgmt_proto *mgmt) static void stop_timer_tc3(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TC3.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TC3.\n");
osmo_timer_del(&mgmt->timer_tc3); osmo_timer_del(&mgmt->timer_tc3);
} }
static void stop_timer_tc8(struct v5x_mgmt_proto *mgmt) static void stop_timer_tc8(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TC8.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TC8.\n");
osmo_timer_del(&mgmt->timer_tc8); osmo_timer_del(&mgmt->timer_tc8);
} }
static void stop_timer_tc9(struct v5x_mgmt_proto *mgmt) static void stop_timer_tc9(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TC9.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TC9.\n");
osmo_timer_del(&mgmt->timer_tc9); osmo_timer_del(&mgmt->timer_tc9);
} }
static void stop_timer_tv1(struct v5x_mgmt_proto *mgmt) static void stop_timer_tv1(struct v5x_mgmt_proto *mgmt)
{ {
LOGP(DV5MGMT, LOGL_DEBUG, "Stop timer TV1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Stop timer TV1.\n");
osmo_timer_del(&mgmt->timer_tv1); osmo_timer_del(&mgmt->timer_tv1);
} }
static void timeout_system(void *data) static void timeout_system(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout timer for system startup delay.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout timer for system startup delay.\n");
v5x_le_mgmt_start(mgmt->interface); v5x_le_mgmt_start(mgmt->interface);
} }
static void timeout_tr1(void *data) static void timeout_tr1(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TR1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TR1.\n");
osmo_fsm_inst_dispatch(mgmt->pstn_rs_fi, V5X_LE_PSTN_RS_E_TIMEOUT_TR1, NULL); osmo_fsm_inst_dispatch(mgmt->pstn_rs_fi, V5X_LE_PSTN_RS_E_TIMEOUT_TR1, NULL);
} }
static void timeout_tr2(void *data) static void timeout_tr2(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TR2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TR2.\n");
osmo_fsm_inst_dispatch(mgmt->pstn_rs_fi, V5X_LE_PSTN_RS_E_TIMEOUT_TR2, NULL); osmo_fsm_inst_dispatch(mgmt->pstn_rs_fi, V5X_LE_PSTN_RS_E_TIMEOUT_TR2, NULL);
} }
static void timeout_tc1(void *data) static void timeout_tc1(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TC1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TC1.\n");
osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC1, NULL); osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC1, NULL);
} }
static void timeout_tc2(void *data) static void timeout_tc2(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TC2.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TC2.\n");
osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC2, NULL); osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC2, NULL);
} }
static void timeout_tc3(void *data) static void timeout_tc3(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TC3.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TC3.\n");
osmo_fsm_inst_dispatch(mgmt->pstn_dl_fi, V5X_LE_PSTN_DL_E_TIMEOUT_TC3, NULL); osmo_fsm_inst_dispatch(mgmt->pstn_dl_fi, V5X_LE_PSTN_DL_E_TIMEOUT_TC3, NULL);
} }
static void timeout_tc8(void *data) static void timeout_tc8(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TC8.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TC8.\n");
osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC8, NULL); osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC8, NULL);
} }
static void timeout_tc9(void *data) static void timeout_tc9(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TC9.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TC9.\n");
osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC9, NULL); osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TC9, NULL);
} }
static void timeout_tv1(void *data) static void timeout_tv1(void *data)
{ {
struct v5x_mgmt_proto *mgmt = data; struct v5x_mgmt_proto *mgmt = data;
LOGP(DV5MGMT, LOGL_DEBUG, "Timeout TV1.\n"); LOGV5IF(mgmt->interface, DV5MGMT, LOGL_DEBUG, "Timeout TV1.\n");
osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TV1, NULL); osmo_fsm_inst_dispatch(mgmt->system_fi, V5X_LE_SYSTEM_E_TIMEOUT_TV1, NULL);
} }
@ -1211,7 +1209,7 @@ static void restart_all_pstn_ports(struct v5x_interface *v5if)
llist_for_each_entry(v5up, &v5if->user_ports, list) { llist_for_each_entry(v5up, &v5if->user_ports, list) {
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_INFO, "Send restart request to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Send restart request to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_restart_req); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_restart_req);
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_restart_compl); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_restart_compl);
} }
@ -1425,14 +1423,14 @@ static void complete_accelerated_alignment(struct v5x_interface *v5if, int ins)
/* a complete set (ISDN/PSTN) was was unblocked, now we send blocking of actual blocked ports */ /* a complete set (ISDN/PSTN) was was unblocked, now we send blocking of actual blocked ports */
if ((ins == UNBLK_ALL_PSTN_ISDN || ins == UNBLK_ALL_PSTN || ins == UNBLK_ALL_ISDN) if ((ins == UNBLK_ALL_PSTN_ISDN || ins == UNBLK_ALL_PSTN || ins == UNBLK_ALL_ISDN)
&& !v5up->le_unblocked) { && !v5up->le_unblocked) {
LOGP(DV5MGMT, LOGL_INFO, " -> Send block indication to %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Send block indication to %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
v5x_port_mph_snd(v5up, MPH_BI); v5x_port_mph_snd(v5up, MPH_BI);
} }
/* a complete set (ISDN/PSTN) was was blocked, now we send unblocking of actual unblocked ports */ /* a complete set (ISDN/PSTN) was was blocked, now we send unblocking of actual unblocked ports */
if ((ins == BLK_ALL_PSTN || ins == BLK_ALL_ISDN) && v5up->le_unblocked) { if ((ins == BLK_ALL_PSTN || ins == BLK_ALL_ISDN) && v5up->le_unblocked) {
LOGP(DV5MGMT, LOGL_INFO, " -> Send unblock request to %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, " -> Send unblock request to %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
v5x_port_mph_snd(v5up, MPH_UBR); v5x_port_mph_snd(v5up, MPH_UBR);
} }
} }
@ -1846,7 +1844,7 @@ void v5x_le_mdl_rcv(struct v5x_interface *v5if, struct v5x_link *v5l, enum v5x_m
case MDL_LAYER_1_FAILURE_ind: case MDL_LAYER_1_FAILURE_ind:
break; break;
default: default:
LOGP(DV5MGMT, LOGL_NOTICE, "Ignoring data link message %d from address = %d\n", prim, dladdr); LOGV5IF(v5if, DV5MGMT, LOGL_NOTICE, "Ignoring data link message %d from address = %d\n", prim, dladdr);
} }
} }
@ -1856,12 +1854,12 @@ void v5x_le_common_ctrl_rcv(struct v5x_interface *v5if, uint8_t cfi, uint8_t var
{ {
struct variant_interface_id vi; struct variant_interface_id vi;
LOGP(DV5MGMT, LOGL_DEBUG, "Received common control message from control protocol. " LOGV5IF(v5if, DV5MGMT, LOGL_DEBUG, "Received common control message from control protocol. "
"(cfi = %d, variant = %d, rej_cause = %d, interface_id = %d)\n", cfi, variant, rej_cause, interface_id); "(cfi = %d, variant = %d, rej_cause = %d, interface_id = %d)\n", cfi, variant, rej_cause, interface_id);
switch (cfi) { switch (cfi) {
/* variant & interface ID */ /* variant & interface ID */
case V5X_CTRL_ID_REQUEST_VARIANT_AND_INTERFACE_ID: case V5X_CTRL_ID_REQUEST_VARIANT_AND_INTERFACE_ID:
LOGP(DV5MGMT, LOGL_INFO, "AN requests variant and interface ID, replying.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "AN requests variant and interface ID, replying.\n");
v5x_le_ctrl_common_snd(v5if, V5X_CTRL_ID_VARIANT_AND_INTERFACE_ID, NULL, &v5if->variant, v5x_le_ctrl_common_snd(v5if, V5X_CTRL_ID_VARIANT_AND_INTERFACE_ID, NULL, &v5if->variant,
&v5if->id); &v5if->id);
break; break;
@ -1879,27 +1877,27 @@ void v5x_le_common_ctrl_rcv(struct v5x_interface *v5if, uint8_t cfi, uint8_t var
break; break;
/* accelerated aligment: request */ /* accelerated aligment: request */
case V5X_CTRL_ID_UNBLK_ALL_REL_PSTN_ISDN_REQUEST: case V5X_CTRL_ID_UNBLK_ALL_REL_PSTN_ISDN_REQUEST:
LOGP(DV5MGMT, LOGL_INFO, "Unblock of all related PSTN and ISDN ports received.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Unblock of all related PSTN and ISDN ports received.\n");
osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_PSTN_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST, osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_PSTN_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST,
(void *)UNBLK_ALL_PSTN_ISDN); (void *)UNBLK_ALL_PSTN_ISDN);
break; break;
case V5X_CTRL_ID_UNBLK_ALL_REL_PSTN_REQUEST: case V5X_CTRL_ID_UNBLK_ALL_REL_PSTN_REQUEST:
LOGP(DV5MGMT, LOGL_INFO, "Unblock of all related PSTN ports received.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Unblock of all related PSTN ports received.\n");
osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_PSTN], V5X_LE_UNBLK_ALL_E_REQUEST, osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_PSTN], V5X_LE_UNBLK_ALL_E_REQUEST,
(void *)UNBLK_ALL_PSTN); (void *)UNBLK_ALL_PSTN);
break; break;
case V5X_CTRL_ID_UNBLK_ALL_REL_ISDN_REQUEST: case V5X_CTRL_ID_UNBLK_ALL_REL_ISDN_REQUEST:
LOGP(DV5MGMT, LOGL_INFO, "Unblock of all related ISDN ports received.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Unblock of all related ISDN ports received.\n");
osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST, osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[UNBLK_ALL_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST,
(void *)UNBLK_ALL_ISDN); (void *)UNBLK_ALL_ISDN);
break; break;
case V5X_CTRL_ID_BLK_ALL_PSTN_REQUEST: case V5X_CTRL_ID_BLK_ALL_PSTN_REQUEST:
LOGP(DV5MGMT, LOGL_INFO, "Block of all related PSTN ports received.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Block of all related PSTN ports received.\n");
osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[BLK_ALL_PSTN], V5X_LE_UNBLK_ALL_E_REQUEST, osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[BLK_ALL_PSTN], V5X_LE_UNBLK_ALL_E_REQUEST,
(void *)BLK_ALL_PSTN); (void *)BLK_ALL_PSTN);
break; break;
case V5X_CTRL_ID_BLK_ALL_ISDN_REQUEST: case V5X_CTRL_ID_BLK_ALL_ISDN_REQUEST:
LOGP(DV5MGMT, LOGL_INFO, "Block of all related ISDN ports received.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_INFO, "Block of all related ISDN ports received.\n");
osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[BLK_ALL_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST, osmo_fsm_inst_dispatch(v5if->mgmt->unblk_all_fi[BLK_ALL_ISDN], V5X_LE_UNBLK_ALL_E_REQUEST,
(void *)BLK_ALL_ISDN); (void *)BLK_ALL_ISDN);
break; break;
@ -1967,7 +1965,7 @@ void v5x_le_common_ctrl_rcv(struct v5x_interface *v5if, uint8_t cfi, uint8_t var
(void *)BLK_ALL_ISDN); (void *)BLK_ALL_ISDN);
break; break;
default: default:
LOGP(DV5MGMT, LOGL_NOTICE, "Ignoring common control message with cfi = %d\n", cfi); LOGV5IF(v5if, DV5MGMT, LOGL_NOTICE, "Ignoring common control message with cfi = %d\n", cfi);
} }
} }
@ -1977,13 +1975,12 @@ void v5x_le_mgmt_port_unblock(struct v5x_user_port *v5up)
if (v5x_le_mgmt_port_is_in_service(v5up)) { if (v5x_le_mgmt_port_is_in_service(v5up)) {
v5x_port_mph_snd(v5up, MPH_UBR); v5x_port_mph_snd(v5up, MPH_UBR);
if (v5up->pstn.proto && v5up->an_unblocked) { if (v5up->pstn.proto && v5up->an_unblocked) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port.\n");
v5up->nr);
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked);
} }
} }
if (!v5up->an_unblocked) { if (!v5up->an_unblocked) {
LOGP(DV5MGMT, LOGL_INFO, "Reply with blocking, because AN is blocked.\n"); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Reply with blocking, because AN is blocked.\n");
uint8_t ctrl = PH_CTRL_BLOCK; uint8_t ctrl = PH_CTRL_BLOCK;
ph_socket_tx_msg(&v5up->ph_socket, v5up->type == V5X_USER_TYPE_ISDN ? 3 : 0, ph_socket_tx_msg(&v5up->ph_socket, v5up->type == V5X_USER_TYPE_ISDN ? 3 : 0,
PH_PRIM_CTRL_IND, &ctrl, 1); PH_PRIM_CTRL_IND, &ctrl, 1);
@ -1996,8 +1993,7 @@ void v5x_le_mgmt_port_block(struct v5x_user_port *v5up)
if (v5x_le_mgmt_port_is_in_service(v5up)) { if (v5x_le_mgmt_port_is_in_service(v5up)) {
v5x_port_mph_snd(v5up, MPH_BI); v5x_port_mph_snd(v5up, MPH_BI);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port.\n");
v5up->nr);
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked);
} }
} }
@ -2011,19 +2007,19 @@ void v5x_le_nat_ph_rcv(struct v5x_user_port *v5up, uint8_t prim, uint8_t *data,
switch (prim) { switch (prim) {
case PH_PRIM_CTRL_REQ: case PH_PRIM_CTRL_REQ:
if (length && *data == PH_CTRL_UNBLOCK) { if (length && *data == PH_CTRL_UNBLOCK) {
LOGP(DV5MGMT, LOGL_INFO, "Received unblocking from LE of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unblocking from LE of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
v5x_le_mgmt_port_unblock(v5up); v5x_le_mgmt_port_unblock(v5up);
} }
if (length && *data == PH_CTRL_BLOCK) { if (length && *data == PH_CTRL_BLOCK) {
LOGP(DV5MGMT, LOGL_INFO, "Received blocking from LE of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received blocking from LE of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
v5x_le_mgmt_port_block(v5up); v5x_le_mgmt_port_block(v5up);
} }
break; break;
case PH_PRIM_ACT_REQ: case PH_PRIM_ACT_REQ:
LOGP(DV5MGMT, LOGL_INFO, "Received activation from LE of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received activation from LE of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
if (!v5up->an_unblocked) { if (!v5up->an_unblocked) {
ph_socket_tx_msg(s, 3, PH_PRIM_DACT_IND, NULL, 0); ph_socket_tx_msg(s, 3, PH_PRIM_DACT_IND, NULL, 0);
break; break;
@ -2031,13 +2027,13 @@ void v5x_le_nat_ph_rcv(struct v5x_user_port *v5up, uint8_t prim, uint8_t *data,
v5x_port_mph_snd(v5up, MPH_AR); v5x_port_mph_snd(v5up, MPH_AR);
break; break;
case PH_PRIM_DACT_REQ: case PH_PRIM_DACT_REQ:
LOGP(DV5MGMT, LOGL_INFO, "Received deactivation from LE of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received deactivation from LE of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
v5x_port_mph_snd(v5up, MPH_DR); v5x_port_mph_snd(v5up, MPH_DR);
break; break;
default: default:
LOGP(DV5MGMT, LOGL_INFO, "Received unknown prim %d from LE for %s port %d.\n", prim, LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unknown prim %d from LE for %s port.\n", prim,
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
} }
} }
@ -2046,53 +2042,53 @@ void v5x_le_port_mph_rcv(struct v5x_user_port *v5up, enum v5x_mph_prim prim, uin
{ {
switch (prim) { switch (prim) {
case MPH_UBR: case MPH_UBR:
LOGP(DV5MGMT, LOGL_INFO, "Received unblocking request from AN of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unblocking request from AN of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
if (v5up->le_unblocked) { if (v5up->le_unblocked) {
LOGP(DV5MGMT, LOGL_INFO, "Reply with unblocking request, because port available at LE.\n"); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Reply with unblocking request, because port available at LE.\n");
v5x_port_mph_snd(v5up, MPH_UBR); v5x_port_mph_snd(v5up, MPH_UBR);
block_unblock_socket(v5up, false); block_unblock_socket(v5up, false);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked);
} }
} else { } else {
LOGP(DV5MGMT, LOGL_INFO, "Reply with blocking indication, because port unavailable at LE.\n"); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Reply with blocking indication, because port unavailable at LE.\n");
v5up->an_unblocked = false; v5up->an_unblocked = false;
v5x_port_mph_snd(v5up, MPH_BI); v5x_port_mph_snd(v5up, MPH_BI);
} }
break; break;
case MPH_UBI: case MPH_UBI:
LOGP(DV5MGMT, LOGL_INFO, "Received unblocking indication from AN of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unblocking indication from AN of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
block_unblock_socket(v5up, false); block_unblock_socket(v5up, false);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port unblocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_unblocked);
} }
break; break;
case MPH_BR: case MPH_BR:
LOGP(DV5MGMT, LOGL_INFO, "Received blocking request from AN of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received blocking request from AN of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
LOGP(DV5MGMT, LOGL_INFO, "Reply with blocking indication.\n"); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Reply with blocking indication.\n");
v5x_port_mph_snd(v5up, MPH_BI); v5x_port_mph_snd(v5up, MPH_BI);
block_unblock_socket(v5up, true); block_unblock_socket(v5up, true);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked);
} }
break; break;
case MPH_BI: case MPH_BI:
LOGP(DV5MGMT, LOGL_INFO, "Received blocking indication from AN of %s port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received blocking indication from AN of %s port.\n",
(v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
block_unblock_socket(v5up, true); block_unblock_socket(v5up, true);
if (v5up->pstn.proto) { if (v5up->pstn.proto) {
LOGP(DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Send port blocked control to PSTN port.\n");
v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked); v5x_le_pstn_mdu_snd(v5up, MDU_CTRL_port_blocked);
} }
break; break;
case MPH_AI: case MPH_AI:
LOGP(DV5MGMT, LOGL_INFO, "Received activation indication from AN of ISDN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received activation indication from AN of ISDN port.\n");
ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_ACT_IND, NULL, 0); ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_ACT_IND, NULL, 0);
break; break;
case MPH_AWI: case MPH_AWI:
@ -2100,15 +2096,15 @@ void v5x_le_port_mph_rcv(struct v5x_user_port *v5up, enum v5x_mph_prim prim, uin
case MPH_DSAI: case MPH_DSAI:
break; break;
case MPH_DI: case MPH_DI:
LOGP(DV5MGMT, LOGL_INFO, "Received deactivation indication from AN of ISDN port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received deactivation indication from AN of ISDN port.\n");
ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_DACT_IND, NULL, 0); ph_socket_tx_msg(&v5up->ph_socket, 3, PH_PRIM_DACT_IND, NULL, 0);
break; break;
case MPH_GI: case MPH_GI:
LOGP(DV5MGMT, LOGL_INFO, "Received performance grading from AN for ISDN port %d: %s\n", v5up->nr, LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received performance grading from AN for ISDN port: %s\n",
(perf_grading) ? "Degraded" : "Normal grade"); (perf_grading) ? "Degraded" : "Normal grade");
break; break;
default: default:
LOGP(DV5MGMT, LOGL_INFO, "Received unknown prim %d from AN for %s port %d.\n", prim, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unknown prim %d from AN for %s port.\n", prim, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
} }
} }
@ -2117,13 +2113,13 @@ void v5x_le_pstn_mdu_rcv(struct v5x_user_port *v5up, enum v5x_mgmt_prim prim)
{ {
switch (prim) { switch (prim) {
case MDU_error_ind: case MDU_error_ind:
LOGP(DV5MGMT, LOGL_NOTICE, "Received MDU-error_indication from PSTN protocol of port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_NOTICE, "Received MDU-error_indication from PSTN protocol of port.\n");
break; break;
case MDU_CTRL_port_restart_ack: case MDU_CTRL_port_restart_ack:
LOGP(DV5MGMT, LOGL_INFO, "Received restart acknowledge from PSTN protocol of port %d.\n", v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received restart acknowledge from PSTN protocol of port.\n");
break; break;
default: default:
LOGP(DV5MGMT, LOGL_INFO, "Received unknown prim %d from PSTN protocol for port %d.\n", prim, v5up->nr); LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Received unknown prim %d from PSTN protocol for port.\n", prim);
} }
} }
@ -2159,47 +2155,47 @@ void v52_le_lcp_mdu_rcv(struct v5x_link *v5l, enum v5x_mgmt_prim prim)
{ {
switch (prim) { switch (prim) {
case MDU_AI: case MDU_AI:
LOGP(DV5MGMT, LOGL_INFO, "Link %d is active.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Link is active.\n");
break; break;
case MDU_DI: case MDU_DI:
LOGP(DV5MGMT, LOGL_INFO, "Link %d is inactive.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Link is inactive.\n");
break; break;
case MDU_LAI: case MDU_LAI:
LOGP(DV5MGMT, LOGL_INFO, "Link %d becomes active in blocked state, try unblocking.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Link becomes active in blocked state, try unblocking.\n");
v52_le_lcp_mdu_snd(v5l, MDU_LUBR); v52_le_lcp_mdu_snd(v5l, MDU_LUBR);
break; break;
case MDU_IDReq: case MDU_IDReq:
LOGP(DV5MGMT, LOGL_INFO, "Remote side perform link ID check of link %d, replying.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Remote side perform link ID check of link, replying.\n");
v52_le_lcp_mdu_snd(v5l, MDU_IDAck); v52_le_lcp_mdu_snd(v5l, MDU_IDAck);
break; break;
case MDU_IDAck: case MDU_IDAck:
break; break;
case MDU_IDRel: case MDU_IDRel:
LOGP(DV5MGMT, LOGL_INFO, "Remote side ID check done.\n"); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Remote side ID check done.\n");
break; break;
case MDU_IDRej: case MDU_IDRej:
break; break;
case MDU_EIg: case MDU_EIg:
break; break;
case MDU_LUBR: case MDU_LUBR:
LOGP(DV5MGMT, LOGL_INFO, "Remote side unblocks link ID %d, replying.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Remote side unblocks link, replying.\n");
v52_le_lcp_mdu_snd(v5l, MDU_LUBR); v52_le_lcp_mdu_snd(v5l, MDU_LUBR);
break; break;
case MDU_LUBI: case MDU_LUBI:
LOGP(DV5MGMT, LOGL_INFO, "Remote side link ID %d is now unblocked.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Remote side link is now unblocked.\n");
break; break;
case MDU_LBI: case MDU_LBI:
LOGP(DV5MGMT, LOGL_INFO, "LCP indicated blocked link ID %d.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "LCP indicated blocked link.\n");
flush_link(v5l); flush_link(v5l);
break; break;
case MDU_LBR: case MDU_LBR:
case MDU_LBRN: case MDU_LBRN:
LOGP(DV5MGMT, LOGL_INFO, "Remote request blocking of link link ID %d, replying.\n", v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Remote request blocking of link link, replying.\n");
flush_link(v5l); flush_link(v5l);
v52_le_lcp_mdu_snd(v5l, MDU_LBI); v52_le_lcp_mdu_snd(v5l, MDU_LBI);
break; break;
default: default:
LOGP(DV5MGMT, LOGL_INFO, "Received unknown prim %d from LCP protocol for link ID %d.\n", prim, v5l->id); LOGV5L(v5l, DV5MGMT, LOGL_INFO, "Received unknown prim %d from LCP protocol for link.\n", prim);
} }
} }
@ -2230,13 +2226,12 @@ void v5x_le_nat_fe_rcv(struct v5x_user_port *v5up, struct msgb *msg)
msgb_pull(msg, 1); msgb_pull(msg, 1);
if (!v5x_le_port_pstn_is_operational(v5up->port_fi)) { if (!v5x_le_port_pstn_is_operational(v5up->port_fi)) {
LOGP(DV5MGMT, LOGL_NOTICE, "Dropping (NAT->LE) message of non-operational PSTN port for L3Addr %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_NOTICE, "Dropping (NAT->LE) message of non-operational PSTN port.");
v5up->nr);
msgb_free(msg); msgb_free(msg);
return; return;
} }
LOGP(DV5MGMT, LOGL_INFO, "FE message: %s NAT -> PSTN_LE of PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "FE message: %s NAT -> PSTN_LE of PSTN port.\n",
get_value_string(v5x_fe_prim_names, prim), v5up->nr); get_value_string(v5x_fe_prim_names, prim));
v5x_le_pstn_fe_snd(v5up, prim, msg); v5x_le_pstn_fe_snd(v5up, prim, msg);
} }
@ -2246,13 +2241,12 @@ void v5x_le_pstn_fe_rcv(struct v5x_user_port *v5up, enum v5x_fe_prim prim, struc
*msgb_push(msg, 1) = prim; *msgb_push(msg, 1) = prim;
if (!v5x_le_port_pstn_is_operational(v5up->port_fi) && prim != FE_disconnect_compl_ind) { if (!v5x_le_port_pstn_is_operational(v5up->port_fi) && prim != FE_disconnect_compl_ind) {
LOGP(DV5MGMT, LOGL_NOTICE, "Dropping (AN->NAT) message of non-operational PSTN port for L3Addr %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_NOTICE, "Dropping (AN->NAT) message of non-operational PSTN port.\n");
v5up->nr);
msgb_free(msg); msgb_free(msg);
return; return;
} }
LOGP(DV5MGMT, LOGL_INFO, "FE message: %s PSTN_LE -> NAT of PSTN port %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "FE message: %s PSTN_LE -> NAT of PSTN port.\n",
get_value_string(v5x_fe_prim_names, prim), v5up->nr); get_value_string(v5x_fe_prim_names, prim));
ph_socket_tx_msg(&v5up->ph_socket, 0, PH_PRIM_DATA_IND, msg->data, msg->len); ph_socket_tx_msg(&v5up->ph_socket, 0, PH_PRIM_DATA_IND, msg->data, msg->len);
msgb_free(msg); msgb_free(msg);
@ -2277,14 +2271,14 @@ void v5x_le_channel_assign(struct v5x_user_port *v5up, int channel)
/* the channels are pre-assigned with V5.1, so only activation state is set */ /* the channels are pre-assigned with V5.1, so only activation state is set */
if (v5if->dialect == V5X_DIALECT_V51) { if (v5if->dialect == V5X_DIALECT_V51) {
if (!v5up->ts[channel - 1]) { if (!v5up->ts[channel - 1]) {
LOGP(DV5MGMT, LOGL_ERROR, "Cannot activate channel, because no TS is assigned for %s port " LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "Cannot activate channel, because no TS is assigned for %s port.\n",
"%d.\n", (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5l->id); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
return; return;
} }
if (v5up->ts[channel - 1]->b_activated) if (v5up->ts[channel - 1]->b_activated)
return; return;
LOGP(DV5MGMT, LOGL_DEBUG, "Activating channel %d for %s port %d at TS %d of link %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Activating channel %d for %s port at TS %d of link %d.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN",
v5up->ts[channel - 1]->nr, v5up->ts[channel - 1]->link->id); v5up->ts[channel - 1]->nr, v5up->ts[channel - 1]->link->id);
ph_activate_req(v5up->ts[channel - 1]); ph_activate_req(v5up->ts[channel - 1]);
return; return;
@ -2300,7 +2294,7 @@ void v5x_le_channel_assign(struct v5x_user_port *v5up, int channel)
found = 0; found = 0;
llist_for_each_entry(v5l, &v5if->links, list) { llist_for_each_entry(v5l, &v5if->links, list) {
if (!v52_le_lcp_is_operational(v5l->fi)) { if (!v52_le_lcp_is_operational(v5l->fi)) {
LOGP(DV5MGMT, LOGL_NOTICE, "While searching for a bearer channel: Skipping link with ID %d, " LOGV5UP(v5up, DV5MGMT, LOGL_NOTICE, "While searching for a bearer channel: Skipping link with ID %d, "
"because it is not operational.\n", v5l->id); "because it is not operational.\n", v5l->id);
continue; continue;
} }
@ -2316,7 +2310,7 @@ void v5x_le_channel_assign(struct v5x_user_port *v5up, int channel)
break; break;
} }
if (!found) { if (!found) {
LOGP(DV5MGMT, LOGL_NOTICE, "No free channel found.\n"); LOGV5UP(v5up, DV5MGMT, LOGL_NOTICE, "No free channel found.\n");
return; return;
} }
@ -2338,14 +2332,14 @@ void v5x_le_channel_unassign(struct v5x_user_port *v5up, int channel)
/* the channels are pre-assigned with V5.1, so only activation state is set */ /* the channels are pre-assigned with V5.1, so only activation state is set */
if (v5if->dialect == V5X_DIALECT_V51) { if (v5if->dialect == V5X_DIALECT_V51) {
if (!v5up->ts[channel - 1]) { if (!v5up->ts[channel - 1]) {
LOGP(DV5MGMT, LOGL_ERROR, "Cannot deactivate channel, because no TS is assigned for %s port " LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "Cannot deactivate channel, because no TS is assigned for %s port.\n",
"%d.\n", (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr); (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN");
return; return;
} }
if (!v5up->ts[channel - 1]->b_activated) if (!v5up->ts[channel - 1]->b_activated)
return; return;
LOGP(DV5MGMT, LOGL_DEBUG, "Deactivating channel %d for %s port %d at TS %d of link %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_DEBUG, "Deactivating channel %d for %s port at TS %d of link %d.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN",
v5up->ts[channel - 1]->nr, v5up->ts[channel - 1]->link->id); v5up->ts[channel - 1]->nr, v5up->ts[channel - 1]->link->id);
ph_deactivate_req(v5up->ts[channel - 1]); ph_deactivate_req(v5up->ts[channel - 1]);
return; return;
@ -2372,18 +2366,18 @@ int v52_le_bcc_mdu_rcv(struct v5x_interface *v5if, uint8_t link_id, uint8_t ts,
int channel = 0; int channel = 0;
if (ts > 31) { if (ts > 31) {
LOGP(DV5MGMT, LOGL_ERROR, "TS %d out of range.\n", ts); LOGV5IF(v5if, DV5MGMT, LOGL_ERROR, "TS %d out of range.\n", ts);
return -EINVAL; return -EINVAL;
} }
v5l = v5x_link_find_id(v5if, link_id); v5l = v5x_link_find_id(v5if, link_id);
if (!v5l) { if (!v5l) {
LOGP(DV5MGMT, LOGL_ERROR, "Invalid link ID %d.\n", link_id); LOGV5IF(v5if, DV5MGMT, LOGL_ERROR, "Invalid link ID %d.\n", link_id);
return -EINVAL; return -EINVAL;
} }
v5up = v5l->ts[ts].v5up; v5up = v5l->ts[ts].v5up;
if (!v5up) { if (!v5up) {
LOGP(DV5MGMT, LOGL_NOTICE, "TS %d of link ID %d is not assigned.\n", ts, link_id); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "TS %d of link ID %d is not assigned.\n", ts, link_id);
return 0; return 0;
} }
if (v5up->ts[0] == &v5l->ts[ts]) if (v5up->ts[0] == &v5l->ts[ts])
@ -2394,13 +2388,13 @@ int v52_le_bcc_mdu_rcv(struct v5x_interface *v5if, uint8_t link_id, uint8_t ts,
switch (prim) { switch (prim) {
case MDU_BCC_allocation_conf: case MDU_BCC_allocation_conf:
LOGP(DV5MGMT, LOGL_INFO, "Assigned channel %d for %s port %d at TS %d of link %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Assigned channel %d for %s port at TS %d of link %d.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, ts, link_id); channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", ts, link_id);
ph_activate_req(v5up->ts[channel - 1]); ph_activate_req(v5up->ts[channel - 1]);
break; break;
case MDU_BCC_deallocation_conf: case MDU_BCC_deallocation_conf:
LOGP(DV5MGMT, LOGL_INFO, "Unassigned channel %d for %s port %d at TS %d of link %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_INFO, "Unassigned channel %d for %s port at TS %d of link %d.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, ts, link_id); channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", ts, link_id);
v5l->ts[ts].v5up = NULL; v5l->ts[ts].v5up = NULL;
v5up->ts[0] = NULL; v5up->ts[0] = NULL;
break; break;
@ -2408,32 +2402,32 @@ int v52_le_bcc_mdu_rcv(struct v5x_interface *v5if, uint8_t link_id, uint8_t ts,
case MDU_BCC_deallocation_reject_ind: case MDU_BCC_deallocation_reject_ind:
if (cause_len < 1) if (cause_len < 1)
break; break;
LOGP(DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port %d at TS %d of link %d: %s.\n", LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port at TS %d of link %d: %s.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, ts, link_id, channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", ts, link_id,
get_value_string(v52_bcc_reject_cause_type_str, cause[0] & 0x7f)); get_value_string(v52_bcc_reject_cause_type_str, cause[0] & 0x7f));
if (cause_len > 1) if (cause_len > 1)
LOGP(DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1)); LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1));
v5l->ts[ts].v5up = NULL; v5l->ts[ts].v5up = NULL;
v5up->ts[0] = NULL; v5up->ts[0] = NULL;
break; break;
case MDU_BCC_protocol_error_ind: case MDU_BCC_protocol_error_ind:
if (cause_len < 1) if (cause_len < 1)
break; break;
LOGP(DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port %d at TS %d of link %d: %s.\n", LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port at TS %d of link %d: %s.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, ts, link_id, channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", ts, link_id,
get_value_string(v5x_cause_type_str, cause[0] & 0x7f)); get_value_string(v5x_cause_type_str, cause[0] & 0x7f));
if (cause_len > 1) if (cause_len > 1)
LOGP(DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1)); LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1));
if (cause_len >= 3 && cause[1] == 0x20 && cause[2] == 0x47) { if (cause_len >= 3 && cause[1] == 0x20 && cause[2] == 0x47) {
LOGP(DV5MGMT, LOGL_ERROR, "AN rejects information-transfer-capability information element, " LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "AN rejects information-transfer-capability information element, "
"please disable via VTY!\n"); "please disable via VTY!\n");
} }
v5l->ts[ts].v5up = NULL; v5l->ts[ts].v5up = NULL;
v5up->ts[0] = NULL; v5up->ts[0] = NULL;
break; break;
default: default:
LOGP(DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port %d at TS %d of link %d.\n", LOGV5UP(v5up, DV5MGMT, LOGL_ERROR, "Failed to (un)assign channel %d for %s port at TS %d of link %d.\n",
channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", v5up->nr, ts, link_id); channel, (v5up->type == V5X_USER_TYPE_PSTN) ? "PSTN" : "ISDN", ts, link_id);
} }
return 0; return 0;
@ -2445,44 +2439,44 @@ int v52_le_bcc_mdu_rcv(struct v5x_interface *v5if, uint8_t link_id, uint8_t ts,
static void switchover_request_link(struct v5x_link *v5l, uint8_t link_id, uint8_t ts) static void switchover_request_link(struct v5x_link *v5l, uint8_t link_id, uint8_t ts)
{ {
LOGP(DV5MGMT, LOGL_NOTICE, "Switch over request from AN to link %d and TS %d.\n", link_id, ts); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Switch over request from AN to link %d and TS %d.\n", link_id, ts);
if (!v5l) { if (!v5l) {
LOGP(DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested link is not primary, nor secondary.\n"); LOGV5L(v5l, DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested link is not primary, nor secondary.\n");
v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts, v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts,
V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_PROV); V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_PROV);
return; return;
} }
if (ts != v5l->c_channel[0].ts->nr) { if (ts != v5l->c_channel[0].ts->nr) {
LOGP(DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested TS is not a C-channel.\n"); LOGV5L(v5l, DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested TS is not a C-channel.\n");
v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts, v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts,
V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_PROV); V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_PROV);
return; return;
} }
if (!v52_le_lcp_is_operational(v5l->fi)) { if (!v52_le_lcp_is_operational(v5l->fi)) {
LOGP(DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested link is not operational.\n"); LOGV5L(v5l,DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested link is not operational.\n");
v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts, v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts,
V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_OPER); V52_PP_REJECT_CAUSE_T_TARGET_CC_NOT_OPER);
return; return;
} }
if (v5l == v5l->interface->cc_link) { if (v5l == v5l->interface->cc_link) {
LOGP(DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested allocation exists already.\n"); LOGV5L(v5l, DV5MGMT, LOGL_ERROR, " -> Rejecting, because requested allocation exists already.\n");
v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts, v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_rej, link_id, ts,
V52_PP_REJECT_CAUSE_T_ALLOC_EXISTS_ALREADY); V52_PP_REJECT_CAUSE_T_ALLOC_EXISTS_ALREADY);
return; return;
} }
LOGP(DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN.\n"); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN.\n");
v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_com, link_id, ts, 0); v52_le_pp_mdu_snd(v5l->interface, MDU_Protection_switch_over_com, link_id, ts, 0);
} }
static void switchover_request(struct v5x_interface *v5if) static void switchover_request(struct v5x_interface *v5if)
{ {
LOGP(DV5MGMT, LOGL_NOTICE, "Switch over request from AN, due to link failure.\n"); LOGV5IF(v5if, DV5MGMT, LOGL_NOTICE, "Switch over request from AN, due to link failure.\n");
if (v5if->primary_link == v5if->cc_link) { if (v5if->primary_link == v5if->cc_link) {
LOGP(DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN. (go to secondary link)\n"); LOGV5IF(v5if, DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN. (go to secondary link)\n");
v52_le_pp_mdu_snd(v5if, MDU_Protection_switch_over_com, v5if->secondary_link->id, 16, 0); v52_le_pp_mdu_snd(v5if, MDU_Protection_switch_over_com, v5if->secondary_link->id, 16, 0);
} }
if (v5if->secondary_link == v5if->cc_link) { if (v5if->secondary_link == v5if->cc_link) {
LOGP(DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN. (go to primary link)\n"); LOGV5IF(v5if, DV5MGMT, LOGL_NOTICE, "Sending switch over command to AN. (go to primary link)\n");
v52_le_pp_mdu_snd(v5if, MDU_Protection_switch_over_com, v5if->primary_link->id, 16, 0); v52_le_pp_mdu_snd(v5if, MDU_Protection_switch_over_com, v5if->primary_link->id, 16, 0);
} }
} }
@ -2500,9 +2494,9 @@ int v52_le_pp_mdu_rcv(struct v5x_interface *v5if, enum v5x_mgmt_prim prim, uint8
switch (prim) { switch (prim) {
case MDU_Protection_switch_over_ack: case MDU_Protection_switch_over_ack:
LOGP(DV5MGMT, LOGL_NOTICE, "Switch over request from LE to link %d and TS %d was acked.\n", link_id, LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Switch over request from LE to link %d and TS %d was acked.\n", link_id,
ts); ts);
LOGP(DV5MGMT, LOGL_NOTICE, "Performing switch over.\n"); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Performing switch over.\n");
if (v5l) if (v5l)
v5if->cc_link = v5l; v5if->cc_link = v5l;
break; break;
@ -2515,35 +2509,35 @@ int v52_le_pp_mdu_rcv(struct v5x_interface *v5if, enum v5x_mgmt_prim prim, uint8
case MDU_Protection_switch_over_reject_ind: case MDU_Protection_switch_over_reject_ind:
if (cause_len < 1) if (cause_len < 1)
break; break;
LOGP(DV5MGMT, LOGL_ERROR, "Switch over to link %d and TS %d was rejected by AN: %s.\n", link_id, ts, LOGV5L(v5l, DV5MGMT, LOGL_ERROR, "Switch over to link %d and TS %d was rejected by AN: %s.\n", link_id, ts,
get_value_string(v52_pp_reject_cause_type_str, cause[0] & 0x7f)); get_value_string(v52_pp_reject_cause_type_str, cause[0] & 0x7f));
break; break;
case MDU_Protection_switch_over_error_ind: case MDU_Protection_switch_over_error_ind:
LOGP(DV5MGMT, LOGL_NOTICE, "Switch over request from LE to link %d and TS %d failed.\n", link_id, ts); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Switch over request from LE to link %d and TS %d failed.\n", link_id, ts);
break; break;
case MDU_Protection_reset_SN_ind: case MDU_Protection_reset_SN_ind:
LOGP(DV5MGMT, LOGL_NOTICE, "AN resets serial numbers at Protection protocol.\n"); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "AN resets serial numbers at Protection protocol.\n");
break; break;
case MDU_Protection_reset_SN_com: case MDU_Protection_reset_SN_com:
LOGP(DV5MGMT, LOGL_NOTICE, "LE resets serial numbers at Protection protocol.\n"); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "LE resets serial numbers at Protection protocol.\n");
break; break;
case MDU_Protection_reset_SN_ack: case MDU_Protection_reset_SN_ack:
LOGP(DV5MGMT, LOGL_NOTICE, "AN acknowledges reset serial numbers at Protection protocol.\n"); LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "AN acknowledges reset serial numbers at Protection protocol.\n");
break; break;
case MDU_Protection_reset_SN_error_ind: case MDU_Protection_reset_SN_error_ind:
LOGP(DV5MGMT, LOGL_NOTICE, "Switch over request failed, due to serial numbers reset at Protection " LOGV5L(v5l, DV5MGMT, LOGL_NOTICE, "Switch over request failed, due to serial numbers reset at Protection "
"protocol.\n"); "protocol.\n");
break; break;
case MDU_Protection_protocol_error_ind: case MDU_Protection_protocol_error_ind:
if (cause_len < 1) if (cause_len < 1)
break; break;
LOGP(DV5MGMT, LOGL_ERROR, "Protocol error: %s.\n", LOGV5L(v5l, DV5MGMT, LOGL_ERROR, "Protocol error: %s.\n",
get_value_string(v5x_cause_type_str, cause[0] & 0x7f)); get_value_string(v5x_cause_type_str, cause[0] & 0x7f));
if (cause_len > 1) if (cause_len > 1)
LOGP(DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1)); LOGV5L(v5l, DV5MGMT, LOGL_ERROR, " -> Diagnostic: %s\n", osmo_hexdump(cause + 1, cause_len - 1));
break; break;
default: default:
LOGP(DV5MGMT, LOGL_ERROR, "Unknown message primitive %d.\n", prim); LOGV5L(v5l, DV5MGMT, LOGL_ERROR, "Unknown message primitive %d.\n", prim);
} }
return 0; return 0;

4
src/v5x_le_port_fsm.c
View File

@ -868,7 +868,7 @@ void v5x_le_port_isdn_fe_rcv(struct v5x_user_port *v5up, uint8_t cfe, uint8_t pe
event = V5X_CUP_LE_FE206_PREFORMANCE_GRADING_IND; event = V5X_CUP_LE_FE206_PREFORMANCE_GRADING_IND;
break; break;
default: default:
LOGP(DV5PORT, LOGL_NOTICE, "Received cfe %d not valid at this protocol\n", cfe); LOGV5UP(v5up, DV5PORT, LOGL_NOTICE, "Received cfe %d not valid at this protocol\n", cfe);
break; break;
} }
@ -902,7 +902,7 @@ void v5x_port_mph_snd(struct v5x_user_port *v5up, enum v5x_mph_prim prim)
event = V5X_CUP_LE_MPH_DU_BLOCK_DCHAN_REQ; event = V5X_CUP_LE_MPH_DU_BLOCK_DCHAN_REQ;
break; break;
default: default:
LOGP(DV5PORT, LOGL_NOTICE, "Got invalid prim %d at this protocol\n", prim); LOGV5UP(v5up, DV5PORT, LOGL_NOTICE, "Got invalid prim %d at this protocol\n", prim);
return; return;
} }

28
src/v5x_protocol.c
View File

@ -398,10 +398,10 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
switch (odp->oph.primitive) { switch (odp->oph.primitive) {
case PRIM_DL_DATA: case PRIM_DL_DATA:
LOGP(DV5, LOGL_DEBUG, "DL-DATA indication received (ldaddr=%d)\n", dladdr); LOGV5IF(v5if, DV5, LOGL_DEBUG, "DL-DATA indication received (ldaddr=%d)\n", dladdr);
break; break;
case PRIM_DL_EST: case PRIM_DL_EST:
LOGP(DV5, LOGL_DEBUG, "DL-EST indication received (ldaddr=%d)\n", dladdr); LOGV5IF(v5if, DV5, LOGL_DEBUG, "DL-EST indication received (ldaddr=%d)\n", dladdr);
switch (dladdr) { switch (dladdr) {
case V5X_DLADDR_CTRL: case V5X_DLADDR_CTRL:
case V5X_DLADDR_PSTN: case V5X_DLADDR_PSTN:
@ -415,7 +415,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
} }
goto out; goto out;
case PRIM_DL_REL: case PRIM_DL_REL:
LOGP(DV5, LOGL_DEBUG, "DL-REL indication received (ldaddr=%d)\n", dladdr); LOGV5IF(v5if, DV5, LOGL_DEBUG, "DL-REL indication received (ldaddr=%d)\n", dladdr);
switch (dladdr) { switch (dladdr) {
case V5X_DLADDR_CTRL: case V5X_DLADDR_CTRL:
case V5X_DLADDR_PSTN: case V5X_DLADDR_PSTN:
@ -429,7 +429,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
} }
goto out; goto out;
default: default:
LOGP(DV5, LOGL_NOTICE, "Unhandled prim=%d (ldaddr=%d)\n", odp->oph.primitive, dladdr); LOGV5IF(v5if, DV5, LOGL_NOTICE, "Unhandled prim=%d (ldaddr=%d)\n", odp->oph.primitive, dladdr);
rc = -EINVAL; rc = -EINVAL;
goto out; goto out;
} }
@ -437,13 +437,13 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
l3h = msgb_l3(msg); l3h = msgb_l3(msg);
if (msgb_l3len(msg) < sizeof(*l3h)) { if (msgb_l3len(msg) < sizeof(*l3h)) {
LOGP(DV5, LOGL_ERROR, "Received short message (%u bytes < %lu)\n", msgb_l3len(msg), sizeof(*l3h)); LOGV5IF(v5if, DV5, LOGL_ERROR, "Received short message (%u bytes < %lu)\n", msgb_l3len(msg), sizeof(*l3h));
rc = -EINVAL; rc = -EINVAL;
goto out; goto out;
} }
if (l3h->pdisc != V5X_CTRL_PDISC) { if (l3h->pdisc != V5X_CTRL_PDISC) {
LOGP(DV5, LOGL_ERROR, "Received unsupported protocol discriminator 0x%02x\n", l3h->pdisc); LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported protocol discriminator 0x%02x\n", l3h->pdisc);
rc = -EINVAL; rc = -EINVAL;
goto out; goto out;
} }
@ -453,7 +453,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
if (rc < 0) if (rc < 0)
goto out; goto out;
LOGP(DV5, LOGL_DEBUG, "Received message from AN with msg_type %d\n", l3h->msg_type); LOGV5IF(v5if, DV5, LOGL_DEBUG, "Received message from AN with msg_type %d\n", l3h->msg_type);
switch (dladdr) { switch (dladdr) {
case V5X_DLADDR_PSTN: case V5X_DLADDR_PSTN:
@ -479,7 +479,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported PSTN message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported PSTN message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
break; break;
@ -496,7 +496,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported CTRL message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported CTRL message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
break; break;
@ -518,7 +518,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported BCC message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported BCC message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
break; break;
@ -537,7 +537,7 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported PROTECTION message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported PROTECTION message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
break; break;
@ -550,13 +550,13 @@ int v5x_dl_rcv(struct osmo_dlsap_prim *odp, uint16_t dladdr, void *rx_cbdata)
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported LCP message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported LCP message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
break; break;
default: default:
rc = -ENOTSUP; rc = -ENOTSUP;
LOGP(DV5, LOGL_ERROR, "Received unsupported message type %s\n", LOGV5IF(v5if, DV5, LOGL_ERROR, "Received unsupported message type %s\n",
osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type)); osmo_tlv_prot_msg_name(&v5x_ctrl_msg_tlv, l3h->msg_type));
} }
@ -592,7 +592,7 @@ int v5x_dl_snd(struct v5x_interface *v5if, uint16_t dladdr, struct msgb *msg)
} }
if (!li) { if (!li) {
LOGP(DV5, LOGL_ERROR, "No instance for dladdr %d.\n", dladdr); LOGV5IF(v5if, DV5, LOGL_ERROR, "No instance for dladdr %d.\n", dladdr);
msgb_free(msg); msgb_free(msg);
return -EINVAL; return -EINVAL;
} }