Project

General

Profile

Bug #3391

SCCPlite SIGTRAN never sends an IPA PING; ipa_asp_fsm_priv->pong_timer exists but is never used

Added by neels 12 days ago. Updated 12 days ago.

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

0%

Estimated time:
Spec Reference:

Description

Testing the new osmo-bsc against an SCCPlite MSC, I notice that no IPA PING is emitted as with the legacy osmo-bsc.
Hence the SCCPlite MSC never accepts the new osmo-bsc as valid IPA peer, ignoring all BSSMAP messages.

Looking at the code, I see that libosmo-sccp only receives IPA_MSGT_PING and _PONG, but apparently never emits these messages.
I also notice that ipa_asp_fsm_priv contains a pong_timer that should presumably wait after an emitted PING, but is never started.

  • IIUC the xua_asp_fsm should emit an IPA PING as soon as it notices an established IPA link.
  • It seems odd that in an FSM, we have an osmo_timer as well. Why is it not a distinct state with a state timeout?

Related issues

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

History

#1 Updated by neels 12 days 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.

#2 Updated by neels 6 days ago

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

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)