Project

General

Profile

Actions
Copy link

Bug #3391

closed

SCCPlite SIGTRAN fails to acknowledge an IPA Identity ACK when the connection is established, expects Identity GET instead

Added by neels almost 6 years ago. Updated over 5 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
neels
Target version:
-
Start date:
07/10/2018
Due date:
% Done:

100%

Spec Reference:

Description

Testing the new osmo-bsc against an SCCPlite MSC, I notice that the initial IPA Identity ACK received from the MSC is disallowed by the FSM, and hence the connection is not accepted.

(Various issues have crept into this ticket, I'm editing this to reduce to the IPA Identity ACK reception.)

Related issues

Related to OsmoBSC - Bug #2544: IPA/SCCPlite not fully supported from new osmo-bsc.gitResolvedneels10/06/2017

Actions
Actions
Copy link
 #1

Updated by neels almost 6 years ago

(disclaimer: I'm completely unfamiliar with the xua_asp_fsm, just trying to collect facts)

  • Right from the start, upon connecting, we receive an IPA IDENTITY ACK. The ipa_asp_fsm seems to be expecting an IPA IDENTITY GET instead:
    DLSS7 DEBUG fsm.c:299 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{ASP_DOWN}: Allocated
DLSS7 DEBUG xua_asp_fsm.c:1104 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{ASP_DOWN}: Received Event M-ASP_UP.req
DLSS7 DEBUG xua_asp_fsm.c:788 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{ASP_DOWN}: State change to WAIT_ID_GET (T3, 10s)
DLSCCP NOTICE sccp_user.c:481 msc-0: Using ASP instance asp-clnt-msc-0
DLSCCP NOTICE sccp_user.c:484 msc-0: Creating SCCP instance
DLSS7 DEBUG osmo_ss7.c:482 registering user=SCCP for SI 3 with priv 0x1fd3e8
DMSC NOTICE osmo_bsc_sigtran.c:519 (msc-0) A-interface: local (BSC) SCCP address: RI=SSN_PC,PC=0.23.3,SSN=BSSAP
DMSC NOTICE osmo_bsc_sigtran.c:521 (msc-0) A-interface: remote (MSC) SCCP address: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
DLSCCP INFO sccp_user.c:88 Binding user 'msc-0' to SSN=254 PC=(no PC)
DMSC DEBUG fsm.c:299 A-RESET(msc-0)[0x1fd538]{DISC}: Allocated
DMSC DEBUG a_reset.c:161 A-RESET(msc-0)[0x1fd538]{DISC}: State change to DISC (T4, 2s)
DHODEC DEBUG handover_decision_2.c:143 HO algorithm 2: next periodical congestion check in 10 seconds
DLINP DEBUG stream.c:258 connection done.
DLSS7 INFO osmo_ss7.c:1472 asp-asp-clnt-msc-0: Client connected (r=172.31.0.200:5000<->l=172.31.49.100:44375)
DLSS7 DEBUG osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Received Event M-ASP_UP.req
DLSS7 ERROR osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Event M-ASP_UP.req not permitted
DLINP DEBUG stream.c:275 connected read
DLINP DEBUG stream.c:189 message received
DLSS7 DEBUG osmo_ss7.c:1513 asp-asp-clnt-msc-0: ipa_cli_read_cb(): ipa_msg_recv_buffered() returned 1
DLSS7 DEBUG ipa.c:95 asp-asp-clnt-msc-0: ipa_rx_msg_ccm:[L1]> 00 01 fe [L2]> 06 
DLSS7 DEBUG ipa.c:100 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Received Event IPA_CCM_ID_ACK
DLSS7 ERROR ipa.c:100 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Event IPA_CCM_ID_ACK not permitted
DMSC DEBUG fsm.c:189 A-RESET(msc-0)[0x1fd538]{DISC}: Timeout of T4
DMSC NOTICE a_reset.c:106 A-RESET(msc-0)[0x1fd538]{DISC}: (re)sending BSSMAP RESET message...
  • I can hack the FSM to expect an ID_ACK instead, which causes osmo-bsc to also send an ID_ACK to the MSC.
    From then on I do receive BSSMAP Reset ACKs from the MSC -- though these don't seem to be received by osmo-bsc yet.
  • osmo-bsc then repeatedly BSSMAP Resets and receives ACKs every time.
    --- a/src/xua_asp_fsm.c
+++ b/src/xua_asp_fsm.c
@@ -785,7 +785,7 @@ static void ipa_asp_fsm_down(struct osmo_fsm_inst *fi, uint32_t event, void *dat
                        }
                } else {
                        /* Client: We simply wait for an ID GET */
-                       osmo_fsm_inst_state_chg(fi, IPA_ASP_S_WAIT_ID_GET, 10, T_WAIT_ID_GET);
+                       osmo_fsm_inst_state_chg(fi, IPA_ASP_S_WAIT_ID_ACK, 10, T_WAIT_ID_ACK);
                }
                break;
        }
@@ -986,6 +986,7 @@ static const struct osmo_fsm_state ipa_asp_states[] = {
                .in_event_mask = S(XUA_ASP_E_M_ASP_UP_REQ) |
                                 S(XUA_ASP_E_SCTP_EST_IND),
                .out_state_mask = S(IPA_ASP_S_WAIT_ID_GET) |
+                                 S(IPA_ASP_S_WAIT_ID_ACK) |
                                  S(IPA_ASP_S_WAIT_ID_RESP),
                .name = "ASP_DOWN",
                .action = ipa_asp_fsm_down,


    20180710152255573 DLSS7 DEBUG fsm.c:299 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{ASP_DOWN}: Allocated
20180710152255575 DLSS7 DEBUG xua_asp_fsm.c:1120 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{ASP_DOWN}: Received Event M-ASP_UP.req
20180710152255577 DLSS7 DEBUG xua_asp_fsm.c:803 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{ASP_DOWN}: State change to WAIT_ID_ACK (T2, 10s)   <-------
20180710152255577 DLSCCP NOTICE sccp_user.c:481 msc-0: Using ASP instance asp-clnt-msc-0
20180710152255578 DLSCCP NOTICE sccp_user.c:484 msc-0: Creating SCCP instance
20180710152255579 DLSS7 DEBUG osmo_ss7.c:482 registering user=SCCP for SI 3 with priv 0x1fd3e0
20180710152255580 DMSC NOTICE osmo_bsc_sigtran.c:519 (msc-0) A-interface: local (BSC) SCCP address: RI=SSN_PC,PC=0.23.3,SSN=BSSAP
20180710152255582 DMSC NOTICE osmo_bsc_sigtran.c:521 (msc-0) A-interface: remote (MSC) SCCP address: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
20180710152255584 DLSCCP INFO sccp_user.c:88 Binding user 'msc-0' to SSN=254 PC=(no PC)
20180710152255585 DMSC DEBUG fsm.c:299 A-RESET(msc-0)[0x1fd530]{DISC}: Allocated
20180710152255586 DMSC DEBUG a_reset.c:161 A-RESET(msc-0)[0x1fd530]{DISC}: State change to DISC (T4, 2s)
20180710152255586 DHODEC DEBUG handover_decision_2.c:143 HO algorithm 2: next periodical congestion check in 10 seconds
20180710152255612 DLINP DEBUG stream.c:258 connection done.
20180710152255613 DLSS7 INFO osmo_ss7.c:1472 asp-asp-clnt-msc-0: Client connected (r=172.31.0.200:5000<->l=172.31.49.100:44247)
20180710152255615 DLSS7 DEBUG osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{WAIT_ID_ACK}: Received Event M-ASP_UP.req
20180710152255616 DLSS7 ERROR osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{WAIT_ID_ACK}: Event M-ASP_UP.req not permitted
20180710152255654 DLINP DEBUG stream.c:275 connected read
20180710152255654 DLINP DEBUG stream.c:189 message received
20180710152255655 DLSS7 DEBUG osmo_ss7.c:1513 asp-asp-clnt-msc-0: ipa_cli_read_cb(): ipa_msg_recv_buffered() returned 1
20180710152255657 DLSS7 DEBUG ipa.c:95 asp-asp-clnt-msc-0: ipa_rx_msg_ccm:[L1]> 00 01 fe [L2]> 06 
20180710152255658 DLSS7 DEBUG ipa.c:100 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{WAIT_ID_ACK}: Received Event IPA_CCM_ID_ACK                      <--------
20180710152255661 DLSS7 DEBUG xua_asp_fsm.c:928 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{WAIT_ID_ACK}: State change to ASP_ACTIVE (no timeout)
20180710152255663 DLSS7 DEBUG xua_asp_fsm.c:404 XUA_AS(as-clnt-msc-0)[0x1cf7a8]{AS_DOWN}: Received Event ASPAS-ASP_INACTIVE.ind
20180710152255664 DLSS7 DEBUG xua_as_fsm.c:183 XUA_AS(as-clnt-msc-0)[0x1cf7a8]{AS_DOWN}: State change to AS_INACTIVE (no timeout)
20180710152255665 DLSS7 DEBUG xua_asp_fsm.c:404 XUA_AS(as-clnt-msc-0)[0x1cf7a8]{AS_INACTIVE}: Received Event ASPAS-ASP_ACTIVE.ind
20180710152255666 DLSS7 DEBUG xua_as_fsm.c:241 XUA_AS(as-clnt-msc-0)[0x1cf7a8]{AS_INACTIVE}: State change to AS_ACTIVE (no timeout)
20180710152255699 DLINP DEBUG stream.c:275 connected read
20180710152255699 DLINP DEBUG stream.c:189 message received
20180710152255700 DLSS7 DEBUG osmo_ss7.c:1513 asp-asp-clnt-msc-0: ipa_cli_read_cb(): ipa_msg_recv_buffered() returned 1
20180710152255701 DLSS7 DEBUG ipa.c:95 asp-asp-clnt-msc-0: ipa_rx_msg_ccm:[L1]> 00 01 fe [L2]> 01 
20180710152255702 DLSS7 DEBUG ipa.c:112 IPA_ASP(asp-clnt-msc-0)[0x1cf4a8]{ASP_ACTIVE}: Received Event ASPSM_BEAT_ACK
20180710152257587 DMSC DEBUG fsm.c:189 A-RESET(msc-0)[0x1fd530]{DISC}: Timeout of T4
20180710152257587 DMSC NOTICE a_reset.c:106 A-RESET(msc-0)[0x1fd530]{DISC}: (re)sending BSSMAP RESET message...     <----- this is actually ACKed (seen in tcpdump), osmo-bsc doesn't notice...
20180710152257588 DMSC NOTICE osmo_bsc_sigtran.c:92 Sending RESET to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP
20180710152257588 DLSCCP DEBUG sccp_scoc.c:1615 Received SCCP User Primitive N-UNITDATA.request)
20180710152257589 DLSS7 DEBUG sccp_scrc.c:420 sccp_scrc_rx_sclc_msg:  HDR=(CL:CLDT,V=0,LEN=0),
    PART(T=Routing Context,L=4,D=00000000),
    PART(T=Protocol Class,L=4,D=00000000),
    PART(T=Source Address,L=12,D=0002000380030008000000fe),
    PART(T=Destination Address,L=12,D=0002000380030008000000fe),
    PART(T=Sequence Control,L=4,D=00000000),
    PART(T=Data,L=6,D=000430040120)
20180710152257589 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0103) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152257589 DLSUA DEBUG sua.c:439 SUA IEI 0x0103 pos 4/12: subpart tag 0x8003, len 8
20180710152257590 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0103) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152257590 DLSUA DEBUG sua.c:439 SUA IEI 0x0103 pos 4/12: subpart tag 0x8003, len 8
20180710152257590 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0102) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152257590 DLSUA DEBUG sua.c:439 SUA IEI 0x0102 pos 4/12: subpart tag 0x8003, len 8
20180710152257591 DLSS7 DEBUG osmo_ss7_hmrt.c:278 m3ua_hmdc_rx_from_l2(): dpc=0=0.0.0 not local, message is for routing
20180710152257591 DLSS7 DEBUG osmo_ss7_hmrt.c:227 Found route for dpc=0=0.0.0: pc=0=0.0.0 mask=0x0=0.0.0 via AS as-clnt-msc-0 proto=ipa
20180710152257591 DMSC DEBUG a_reset.c:110 A-RESET(msc-0)[0x1fd530]{DISC}: State change to DISC (T4, 2s)
20180710152257592 DLINP DEBUG stream.c:279 connected write
20180710152257592 DLINP DEBUG stream.c:204 sending data
20180710152257596 DLINP DEBUG stream.c:279 connected write
20180710152257600 DLINP DEBUG stream.c:204 sending data
20180710152258618 DLINP DEBUG stream.c:275 connected read
20180710152258621 DLINP DEBUG stream.c:189 message received
20180710152258621 DLSS7 DEBUG osmo_ss7.c:1513 asp-asp-clnt-msc-0: ipa_cli_read_cb(): ipa_msg_recv_buffered() returned 19
20180710152258623 DLSUA DEBUG sccp2sua.c:333 Parsed Addr: RI=2,PC=1196,SSN=254
20180710152258625 DLSUA DEBUG sccp2sua.c:333 Parsed Addr: RI=2,PC=100,SSN=254
20180710152258626 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0103) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152258628 DLSUA DEBUG sua.c:439 SUA IEI 0x0103 pos 4/12: subpart tag 0x8003, len 8
20180710152258629 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0102) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152258630 DLSUA DEBUG sua.c:439 SUA IEI 0x0102 pos 4/12: subpart tag 0x8003, len 8
20180710152258632 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0103) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152258632 DLSUA DEBUG sua.c:439 SUA IEI 0x0103 pos 4/12: subpart tag 0x8003, len 8
20180710152258634 DLSUA DEBUG sua.c:385 sua_addr_parse_part(IEI=0x0102) (12) 00 02 00 03 80 03 00 08 00 00 00 fe 
20180710152258636 DLSUA DEBUG sua.c:439 SUA IEI 0x0102 pos 4/12: subpart tag 0x8003, len 8
20180710152258637 DLSS7 DEBUG osmo_ss7_hmrt.c:278 m3ua_hmdc_rx_from_l2(): dpc=0=0.0.0 not local, message is for routing
20180710152258637 DLSS7 DEBUG osmo_ss7_hmrt.c:227 Found route for dpc=0=0.0.0: pc=0=0.0.0 mask=0x0=0.0.0 via AS as-clnt-msc-0 proto=ipa
20180710152258638 DLINP DEBUG stream.c:279 connected write
20180710152258639 DLINP DEBUG stream.c:204 sending data
20180710152258641 DLINP DEBUG stream.c:279 connected write
20180710152258642 DLINP DEBUG stream.c:204 sending data
20180710152259592 DMSC DEBUG fsm.c:189 A-RESET(msc-0)[0x1fd530]{DISC}: Timeout of T4
20180710152259594 DMSC NOTICE a_reset.c:106 A-RESET(msc-0)[0x1fd530]{DISC}: (re)sending BSSMAP RESET message...              <---------- and RESETs again; repeat.
  • Though this seems to lead in the right direction, I'm still not seeing IPA PING emitted.
    I tried to hack an IPA PING in there but it seems to be at the wrong place...
  • All the while I'm also seeing, early on in the IPA link establishment, apparently non-fatal:
    DLSS7 DEBUG osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Received Event M-ASP_UP.req
DLSS7 ERROR osmo_ss7.c:1480 IPA_ASP(asp-clnt-msc-0)[0x1cf4b0]{WAIT_ID_GET}: Event M-ASP_UP.req not permitted

I could start to dive into this, but it would actually be good to get feedback from laforge
(whenever you have time) so that I don't spin off into a weird direction from not knowing the code base well enough.

Actions
Copy link
 #2

Updated by neels almost 6 years ago

  • Related to Bug #2544: IPA/SCCPlite not fully supported from new osmo-bsc.git added
Actions
Copy link
 #3

Updated by neels over 5 years ago

  • Status changed from New to In Progress
  • Assignee set to neels
  • % Done changed from 0 to 90

The IPA ping-pong actually seems to be fine, the only problem that needs solving is the IPA Identity ACK:
https://gerrit.osmocom.org/c/libosmo-sccp/+/10162

Actions
Copy link
 #4

Updated by neels over 5 years ago

  • Subject changed from SCCPlite SIGTRAN never sends an IPA PING; ipa_asp_fsm_priv->pong_timer exists but is never used to SCCPlite SIGTRAN fails to acknowledge an IPA Identity ACK when the connection is established, expects Identity GET instead
Actions
Copy link
 #5

Updated by neels over 5 years ago

  • Description updated (diff)
Actions
Copy link
 #6

Updated by neels over 5 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 90 to 100

Testing against one specific SCCPlite MSC, the ipa_asp_fsm now works.
The patch that makes it work changes the FSM to expect an IPA ID ACK message instead of an IPA ID GET.
However, other IPA implementations do send a GET and e.g. our libosmo-abis IPA client hard-depends on that.
It remains to be seen whether other MSC vendors have a different IPA bootstrap behavior.
Ideally, our ipa_asp_fsm is able to handle all possible permutations of {ACK,GET}x{sent,not sent} but the particular scenario discussed here works now.

Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)