Skip to main content


Eclipse Community Forums

      Home
Home » Eclipse Projects » Eclipse Titan » titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk
titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848155] Mon, 22 November 2021 12:07 Go to next message
Eclipse UserFriend
Hi,

I'm in the process of writing a CodecPort [1] + Emulation module [2] in order to emulate a HNBGW Iuh, which basically uses a IPL4asp SCTP socket and (de)multiplexes HNBAP and RUA payloads sent/received on the socket based on the sinfo_ppid (20=HNBAP, 19=RUA).

I have a program connecting to the above mentioned socket [3], and then it sends an HNBAP HnbRegisterRequest message to it (I can see in wireshark it properly sets sinfo_ppid=20 in the sctp data chunk section).

But then, in TTCN3, sino_ppid=0 is wrongly reported instead when the message is received:
09:27:22.173733 4 Iuh_Emulation.ttcn:162 Message enqueued on Iuh from system @IPL4asp_Types.ASP_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 54535, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := 0, sinfo_ppid := 0, remSocks := omit, assocId := omit } }, userData := 0, msg := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } id 3
09:27:22.173878 4 Iuh_Emulation.ttcn:162 Incoming message was mapped to @Iuh_CodecPort.Iuh_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 54535, locName := "172.18.33.203", locPort := 29169, msg := { pdu_type := IUH_MSG_TYPE_OTHER (2), u := { payload := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } } } id 3


I enabled debug on that port (as per titan.TestPorts.IPL4asp/src/IPL4asp_PT.cc), and I see the C++ code is already reporting an incorrect sinfo_ppid:
13:00:14.303074 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 9
13:00:14.303692 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 1 READABLE   sock: 9, type: 3, sslState: 0
13:00:14.304114 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: incoming connection requested
13:00:14.304647 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER: ConnAdd enter: type: 4, ssl_tls_type: 0, sock: 10, parentIx: 1
13:00:14.304945 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: connId: 2
13:00:14.306089 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: leave: sockListCnt: 2
13:00:14.306933 4 Iuh_Emulation.ttcn:162 Message enqueued on Iuh from system @Socket_API_Definitions.PortEvent : { connOpened := { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, userData := 0 } } id 1
13:00:14.307468 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
13:00:14.308031 4 Iuh_Emulation.ttcn:175 Matching on port Iuh failed: Type of the first message in the queue is not @Iuh_CodecPort.Iuh_RecvFrom.
13:00:14.308645 4 Iuh_Emulation.ttcn:190 Matching on port Iuh { connOpened := { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, userData := 0 } } with { sctpEvent := { sctpAssocChange := ? } } unmatched: First message in the queue does not match the template:
13:00:14.309287 4 Iuh_Emulation.ttcn:191 Matching on port Iuh { connOpened := { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, userData := 0 } } with { sctpEvent := { sctpPeerAddrChange := ? } } unmatched: First message in the queue does not match the template:
13:00:14.309956 4 Iuh_Emulation.ttcn:194 Matching on port Iuh succeeded:  matched
13:00:14.310325 4 Iuh_Emulation.ttcn:194 Receive operation on port Iuh succeeded, message from system(): @Socket_API_Definitions.PortEvent : { connOpened := { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, userData := 0 } } id 1
13:00:14.310648 4 Iuh_Emulation.ttcn:194 Message with id 1 was extracted from the queue of Iuh.
13:00:14.310927 4 Iuh_Emulation.ttcn:196 Established a new Iuh connection (conn_id=2)
13:00:14.311863 4 Iuh_Emulation.ttcn:198 Sent on HNBAP to TC_hnb_register_request(3) @Iuh_Emulation.IUHEM_Event : { up_down := IUHEM_EVENT_UP (1) }
13:00:14.312657 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
13:00:14.312870 3 Osmocom_Types.ttcn:104 Message enqueued on HNBAP from HNBGW0(4) @Iuh_Emulation.IUHEM_Event : { up_down := IUHEM_EVENT_UP (1) } id 1
13:00:14.313075 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
13:00:14.313360 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
13:00:14.313602 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
13:00:14.314071 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: Notification received
13:00:14.314315 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::handle_event: incoming SCTP_ASSOC_CHANGE event.
13:00:14.314608 4 Iuh_Emulation.ttcn:162 Message enqueued on Iuh from system @Socket_API_Definitions.PortEvent : { sctpEvent := { sctpAssocChange := { clientId := 2, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, sac_state := SCTP_COMM_UP (0) } } } id 2
13:00:14.314901 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
13:00:14.315193 4 Iuh_Emulation.ttcn:175 Matching on port Iuh failed: Type of the first message in the queue is not @Iuh_CodecPort.Iuh_RecvFrom.
13:00:14.315472 4 Iuh_Emulation.ttcn:190 Matching on port Iuh succeeded:  matched
13:00:14.315771 4 Iuh_Emulation.ttcn:190 Receive operation on port Iuh succeeded, message from system(): @Socket_API_Definitions.PortEvent : { sctpEvent := { sctpAssocChange := { clientId := 2, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, sac_state := SCTP_COMM_UP (0) } } } id 2
13:00:14.316036 4 Iuh_Emulation.ttcn:190 Message with id 2 was extracted from the queue of Iuh.
13:00:14.316483 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
13:00:14.316755 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
13:00:14.317028 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
13:00:14.317278 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
13:00:14.317905 4 Iuh_Emulation.ttcn:162 Iuh: PL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: Incoming data (60 bytes): stream = 0, ssn = 0, flags = 0, ppid = 0

13:00:14.318550 4 Iuh_Emulation.ttcn:162 Message enqueued on Iuh from system @IPL4asp_Types.ASP_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := 0, sinfo_ppid := 0, remSocks := omit, assocId := omit } }, userData := 0, msg := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } id 3
13:00:14.319285 4 Iuh_Emulation.ttcn:162 Incoming message was mapped to @Iuh_CodecPort.Iuh_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 40624, locName := "172.18.33.203", locPort := 29169, msg := { pdu_type := IUH_MSG_TYPE_OTHER (2), u := { payload := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } } } id 3
13:00:14.319863 4 Iuh_Emulation.ttcn:162 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave


I also run it through strace, the msg_controllen=0 looks really suspicious:
logs/hnodeb-tester/strace.log.31:13:00:09.604842 recvmsg(4, {msg_name={sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=128->16, msg_iov=[{iov_base="E\0\0T\311\217\0\0@\1\263\27\177\0\0\1\177\0\0\1\0\0n\335\0\37\0\1Y\224\233a"..., iov_len=192}], msg_iovlen=1, msg_control=[{cmsg_len=32, cmsg_level=SOL_SOCKET, cmsg_type=0x1d /* SCM_??? */}], msg_controllen=32, msg_flags=0}, 0) = 84
logs/hnodeb-tester/strace.log.31:13:00:09.605112 recvmsg(4, {msg_namelen=128}, 0) = -1 EAGAIN (Resource temporarily unavailable)
logs/hnodeb-tester/strace.log.31:13:00:10.609540 recvmsg(4, {msg_name={sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, msg_namelen=128->16, msg_iov=[{iov_base="E\0\0T\312\34\0\0@\1\262\212\177\0\0\1\177\0\0\1\0\0\326\312\0\37\0\2Z\224\233a"..., iov_len=192}], msg_iovlen=1, msg_control=[{cmsg_len=32, cmsg_level=SOL_SOCKET, cmsg_type=0x1d /* SCM_??? */}], msg_controllen=32, msg_flags=0}, 0) = 84
logs/hnodeb-tester/strace.log.31:13:00:10.610020 recvmsg(4, {msg_namelen=128}, 0) = -1 EINTR (Interrupted system call)
logs/hnodeb-tester/strace.log.35:13:00:14.313885 recvmsg(10, {msg_name={sa_family=AF_INET, sin_port=htons(40624), sin_addr=inet_addr("172.18.33.20")}, msg_namelen=128->16, msg_iov=[{iov_base="\1\200\0\0\24\0\0\0\0\0\0\0@\0\n\0\256\0\0\0", iov_len=65535}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_EOR|MSG_MORE}, 0) = 20
logs/hnodeb-tester/strace.log.35:13:00:14.317653 recvmsg(10, {msg_name={sa_family=AF_INET, sin_port=htons(40624), sin_addr=inet_addr("172.18.33.20")}, msg_namelen=128->16, msg_iov=[{iov_base="\0\1\0008\0\0\7\0\3\0\f\2@OsmoHNodeB\0\10\0\1\0\0\t\0\3"..., iov_len=65535}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_EOR}, 0) = 60


I see that IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable() (around line 1507) is not using libsctp's sctp_recvmsg, but directly calling getmsg()->recvmsg(). I checked how lksctp-tools [4] implements sctp_recvmsg, and I see that they seem to be doing a better job regarding buffer alignments, etc. and this may be the culprit of derreferring struct sctp_sndrcvinfo pointer incorrectly, which may lead to wrong use of the fields and that may explain sinfo_ppid=0. Other explanation could be that simply there's a kernel bug in old/new recent linux kernels?

titan.core version: 8.0.0
titan.TestPorts.IPL4asp: R.30.E
kernel version: 5.15.3-arch1-1 (x86_64)
userspace: Debian Stretch guest (docker)


[1] git.osmocom.org/osmo-ttcn3-hacks/tree/library/Iuh_CodecPort.ttcn?h=pespin/hnodeb
[2] git.osmocom.org/osmo-ttcn3-hacks/tree/library/Iuh_Emulation.ttcn?h=pespin/hnodeb
[3] git.osmocom.org/osmo-hnodeb/
[4] git://github.com/sctp/lksctp-tools.git
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848164 is a reply to message #1848155] Tue, 23 November 2021 03:05 Go to previous messageGo to next message
Eclipse UserFriend
I'm checking it.
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848168 is a reply to message #1848164] Tue, 23 November 2021 05:20 Go to previous messageGo to next message
Eclipse UserFriend
It seems the receiving of the SCTP_SNDRCV is not enabled for incoming connections.
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848230 is a reply to message #1848168] Thu, 25 November 2021 10:15 Go to previous messageGo to next message
Eclipse UserFriend
Quote:

It seems the receiving of the SCTP_SNDRCV is not enabled for incoming connections.


Hi Gábor, thanks for looking into it. Are you planning to provide a fix for it soon?
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848260 is a reply to message #1848230] Fri, 26 November 2021 02:58 Go to previous messageGo to next message
Eclipse UserFriend
Yes, I'm on it. Can you try the attached file?

Something changed in the newer kernels, because it worked with the older ones.
  • Attachment: IPL4asp_PT.cc
    (Size: 337.23KB, Downloaded 127 times)
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848284 is a reply to message #1848260] Fri, 26 November 2021 07:49 Go to previous messageGo to next message
Eclipse UserFriend
Hi Gábor,

I tested with the new file and I still get the same behavior when running it in my env, sinfo_ppid=0:

12:44:23.282470 4 Iuh_Emulation.ttcn:159 Message enqueued on Iuh from system @Socket_API_Definitions.PortEvent : { sctpEvent := { sctpAssocChange := { clientId := 2, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, sac_state := SCTP_COMM_UP (0) } } } id 2
12:44:23.282707 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
12:44:23.282814 4 Iuh_Emulation.ttcn:172 Matching on port Iuh failed: Type of the first message in the queue is not @Iuh_CodecPort.Iuh_RecvFrom.
12:44:23.282908 4 Iuh_Emulation.ttcn:186 Matching on port Iuh succeeded:  matched
12:44:23.282969 4 Iuh_Emulation.ttcn:186 Receive operation on port Iuh succeeded, message from system(): @Socket_API_Definitions.PortEvent : { sctpEvent := { sctpAssocChange := { clientId := 2, proto := { sctp := { sinfo_stream := omit, sinfo_ppid := omit, remSocks := omit, assocId := omit } }, sac_state := SCTP_COMM_UP (0) } } } id 2
12:44:23.283018 4 Iuh_Emulation.ttcn:186 Message with id 2 was extracted from the queue of Iuh.
12:44:23.283133 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
12:44:23.283222 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
12:44:23.283274 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
12:44:23.283307 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
12:44:23.283368 4 Iuh_Emulation.ttcn:159 Iuh: PL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: Incoming data (60 bytes): stream = 0, ssn = 0, flags = 0, ppid = 0

12:44:23.283913 4 Iuh_Emulation.ttcn:159 Message enqueued on Iuh from system @IPL4asp_Types.ASP_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 52712, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := 0, sinfo_ppid := 0, remSocks := omit, assocId := omit } }, userData := 0, msg := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } id 3
12:44:23.289618 4 Iuh_Emulation.ttcn:159 Incoming message was mapped to @Iuh_CodecPort.Iuh_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 52712, locName := "172.18.33.203", locPort := 29169, msg := { hnbap := { initiatingMessage := { procedureCode := 1, criticality := reject (0), value_ := { hNBRegisterRequest := { protocolIEs := { { id := 3, criticality := reject (0), value_ := { hNB_Identity := { hNB_Identity_Info := '4F736D6F484E6F646542'O ("OsmoHNodeB"), iE_Extensions := omit } } }, { id := 8, criticality := reject (0), value_ := { hNB_Location_Information := { macroCoverageInfo := omit, geographicalCoordinates := omit, iE_Extensions := omit } } }, { id := 9, criticality := reject (0), value_ := { pLMNidentity := '00F110'O } }, { id := 11, criticality := reject (0), value_ := { cellIdentity := '0000000000000000000000000001'B } }, { id := 6, criticality := reject (0), value_ := { lAC := '0002'O } }, { id := 7, criticality := reject (0), value_ := { rAC := '03'O } }, { id := 10, criticality := reject (0), value_ := { sAC := '0004'O } } }, protocolExtensions := omit } } } } } } id 3
12:44:23.289708 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave


The CoecPort actually decodes it as HNBAP because I temporarily patched it to decode HNBAP on sinfo_ppid=0 so I can keep on implementing the HNBAP part while this is being fixed.

[Updated on: Fri, 26 November 2021 07:50] by Moderator

Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848287 is a reply to message #1848155] Fri, 26 November 2021 08:31 Go to previous messageGo to next message
Eclipse UserFriend
Interesting, as It is working for me. I added some more debug printout and doubled the buffer size.
  • Attachment: IPL4asp_PT.cc
    (Size: 337.44KB, Downloaded 120 times)
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848407 is a reply to message #1848287] Wed, 01 December 2021 07:11 Go to previous messageGo to next message
Eclipse UserFriend
I'm wondering what is the specific reason for not using the CMSG_{ALIGN,SPACE,LEN,....} macros is? They have been specified in 1998 and should be present in virtually any OS that supports the socket interface. So they should be portable as they are from an IETF RFC, and don't add new dependencies.

By not using those libc-provided macros, I think one is risking a variety of strange architecture specific problems due to different alignment / padding aspects of the specific combination of CPU, OS and compiler.

Given the above, I'm wondering what is the expected problem/downside of using those standard macros, causing TITAN IPL4asp to explicitly not use them and try it "by hand"?
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848408 is a reply to message #1848407] Wed, 01 December 2021 07:30 Go to previous messageGo to next message
Eclipse UserFriend
I don't know. That part of the code was not written by me, and was written around 2003-2006. It was worked well and based on the strace printout, the problem is not the wrong alignment. The msg_controllen=0 indicates that the linux kernel simply didn't return the information. The refactoring of the code is on list, but first the root cause should be find out.
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848681 is a reply to message #1848408] Mon, 13 December 2021 13:49 Go to previous messageGo to next message
Eclipse UserFriend
Hi Gabor,

sorry, I forgot to mark the "notify me" option and I didn't get last updates here.

I did a test run again, now with the new version of the file you provided with further debug.
I still get ppid=0.

$ cat logs/hnodeb-tester/HNB_Tests.TC_hnb_register_request_accept.merged | grep IPL4asp__PT_PROVIDER:
18:31:42.958738 4 - Iuh: IPL4asp__PT_PROVIDER::set_parameter: enter (name: debug, value: YES)
18:31:42.958803 4 - Iuh: IPL4asp__PT_PROVIDER::user_start: enter
18:31:42.960195 4 Iuh_Emulation.ttcn:136 Iuh: IPL4asp__PT_PROVIDER::user_map(Iuh_CODEC_PT): enter
18:31:42.960970 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: enter, number of options: 0
18:31:42.960985 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: sock: 9
18:31:42.961016 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: Socket option REUSEADDR on socket 9 is set to: 1
18:31:42.961029 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: Setting sctp options sinit_num_ostreams:64,sinit_max_instreams:64, sinit_max_attempts:0, sinit_max_init_timeo:0
18:31:42.961043 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: Setting sctp event options
18:31:42.961063 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::setOptions: leave
18:31:42.961154 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER: ConnAdd enter: type: 3, ssl_tls_type: 0, sock: 9, parentIx: -1
18:31:42.961185 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: new sockListSize: 16
18:31:42.961201 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: connId: 1
18:31:42.961235 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: connId: set ssl options for connId : 1
18:31:42.961256 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::set_ssl_supp_option: set SSL options
18:31:42.961816 4 Iuh_Emulation.ttcn:138 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: leave: sockListCnt: 1
18:31:46.820147 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 9
18:31:46.820743 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 1 READABLE   sock: 9, type: 3, sslState: 0
18:31:46.821227 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: incoming connection requested
18:31:46.821518 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER: ConnAdd enter: type: 4, ssl_tls_type: 0, sock: 10, parentIx: 1
18:31:46.821610 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: connId: 2
18:31:46.822099 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::ConnAdd: leave: sockListCnt: 2
18:31:46.822321 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::setOptions: enter, number of options: 0
18:31:46.822393 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::setOptions: sock: 10
18:31:46.822498 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::setOptions: Setting sctp options sinit_num_ostreams:64,sinit_max_instreams:64, sinit_max_attempts:0, sinit_max_init_timeo:0
18:31:46.822579 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::setOptions: Setting sctp event options
18:31:46.822646 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::setOptions: leave
18:31:46.823993 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
18:31:46.827254 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
18:31:46.827389 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
18:31:46.827475 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
18:31:46.827544 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
18:31:46.827614 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: msg->msg_controllen 96
18:31:46.827878 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::getmsg: msg->msg_controllen 0
18:31:46.828154 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: Notification received
18:31:46.828290 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::handle_event: incoming SCTP_ASSOC_CHANGE event.
18:31:46.828847 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
18:31:46.829402 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
18:31:46.829474 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
18:31:46.829541 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
18:31:46.829596 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
18:31:46.829646 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: msg->msg_controllen 96
18:31:46.829744 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::getmsg: msg->msg_controllen 0
18:31:46.835857 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
18:31:46.843260 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::outgoing_send: ASP Send: enter
18:31:46.843290 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::outgoing_send_core: ASP Send: enter
18:31:46.843330 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::getAndCheckSockType: sock type is: 4
18:31:46.843345 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::outgoing_send_core: ASP Send: calling sendNonBlocking with proto
18:31:46.843370 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::sendNonBlocking: enter: connId: 2
18:31:46.843384 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::sendNonBlocking: fd: 10
18:31:46.843461 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::sendNonBlocking: sctp sinfo: 0, ppid: 335544320
18:31:46.843594 4 Iuh_Emulation.ttcn:163 Iuh: IPL4asp__PT_PROVIDER::sendNonBlocking: leave
18:31:47.850774 4 - Iuh: IPL4asp__PT_PROVIDER::user_unmap(Iuh_CODEC_PT): enter
18:31:47.850807 4 - Iuh: IPL4asp__PT_PROVIDER::user_unmap: There are 2 open connections
18:31:47.850867 4 - Iuh: IPL4asp__PT_PROVIDER::ConnDel: enter: connId: 1
18:31:47.850900 4 - Iuh: IPL4asp__PT_PROVIDER::ConnDel: fd: 9
18:31:47.852359 4 - Iuh: IPL4asp__PT_PROVIDER::ConnFree: enter: connId: 1
18:31:47.852495 4 - Iuh: IPL4asp__PT_PROVIDER::ConnDel: enter: connId: 2
18:31:47.853162 4 - Iuh: IPL4asp__PT_PROVIDER::ConnDel: fd: 10
18:31:47.853561 4 - Iuh: IPL4asp__PT_PROVIDER::ConnFree: enter: connId: 2
18:31:47.853904 4 - Iuh: IPL4asp__PT_PROVIDER::user_stop: enter



It looks like the kernel is returning msg_controllen=0:
18:31:46.827614 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: msg->msg_controllen 96
18:31:46.827878 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::getmsg: msg->msg_controllen 0




The relevant snippet again:
18:31:46.829402 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: enter, fd: 10
18:31:46.829474 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: connId: 2 READABLE   sock: 10, type: 4, sslState: 0
18:31:46.829541 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp message received
18:31:46.829596 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: sctp peername and sockname obtained
18:31:46.829646 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: msg->msg_controllen 96
18:31:46.829744 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::getmsg: msg->msg_controllen 0
18:31:46.829823 4 Iuh_Emulation.ttcn:159 Iuh: PL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: Incoming data (60 bytes): stream = 0, ssn = 0, flags = 0, ppid = 0

18:31:46.830410 4 Iuh_Emulation.ttcn:159 Message enqueued on Iuh from system @IPL4asp_Types.ASP_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 36164, locName := "172.18.33.203", locPort := 29169, proto := { sctp := { sinfo_stream := 0, sinfo_ppid := 0, remSocks := omit, assocId := omit } }, userData := 0, msg := '000100380000070003000C02404F736D6F484E6F64654200080001000009000300F110000B0004000000100006000200020007000103000A00020004'O } id 3
18:31:46.835762 4 Iuh_Emulation.ttcn:159 Incoming message was mapped to @Iuh_CodecPort.Iuh_RecvFrom : { connId := 2, remName := "172.18.33.20", remPort := 36164, locName := "172.18.33.203", locPort := 29169, msg := { hnbap := { initiatingMessage := { procedureCode := 1, criticality := reject (0), value_ := { hNBRegisterRequest := { protocolIEs := { { id := 3, criticality := reject (0), value_ := { hNB_Identity := { hNB_Identity_Info := '4F736D6F484E6F646542'O ("OsmoHNodeB"), iE_Extensions := omit } } }, { id := 8, criticality := reject (0), value_ := { hNB_Location_Information := { macroCoverageInfo := omit, geographicalCoordinates := omit, iE_Extensions := omit } } }, { id := 9, criticality := reject (0), value_ := { pLMNidentity := '00F110'O } }, { id := 11, criticality := reject (0), value_ := { cellIdentity := '0000000000000000000000000001'B } }, { id := 6, criticality := reject (0), value_ := { lAC := '0002'O } }, { id := 7, criticality := reject (0), value_ := { rAC := '03'O } }, { id := 10, criticality := reject (0), value_ := { sAC := '0004'O } } }, protocolExtensions := omit } } } } } } id 3
18:31:46.835857 4 Iuh_Emulation.ttcn:159 Iuh: IPL4asp__PT_PROVIDER::Handle_Fd_Event_Readable: leave
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848682 is a reply to message #1848681] Mon, 13 December 2021 13:52 Go to previous messageGo to next message
Eclipse UserFriend
By the way, I upgraded my system since I run first test, so last test I just run was done with following kernel:
5.15.7-arch1-1 (x86_64)
Archlinux distribution as a host, running TTCN-3 on a debian stretch Docker container.
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1848922 is a reply to message #1848682] Thu, 23 December 2021 12:02 Go to previous messageGo to next message
Eclipse UserFriend
I think I have found the issue: events.sctp_data_io_event was never set properly.

See my fix here:
https://gitlab.eclipse.org/dwillmannv72/titan.TestPorts.IPL4asp/-/commit/0b6a934d07a7a80bb2cf75660a698805d5b34dc7

I also created two merge requests in the SCTPasp and IPL4asp test ports that fix this and a related issue with SCTP_EVENTS.
See here:
https://gitlab.eclipse.org/eclipse/titan/titan.TestPorts.IPL4asp/-/merge_requests/2
https://gitlab.eclipse.org/eclipse/titan/titan.TestPorts.SCTPasp/-/merge_requests/4
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1849459 is a reply to message #1848922] Thu, 20 January 2022 10:11 Go to previous messageGo to next message
Eclipse UserFriend
Just a quick follow-up: All related pull-requests are now merged, and the PPID is correctly presented by both IPL4asp and SCTPasp now.
Re: titan.TestPorts.IPL4asp SCTP socket returning wrong sinfo_ppid=0 when receiving data chunk [message #1849462 is a reply to message #1849459] Thu, 20 January 2022 10:22 Go to previous message
Eclipse UserFriend
Great. It was a little surprise for me that the setsockopt call returned success, but the events were not enabled.
Previous Topic:PTC logging
Next Topic:5G/NG-RAN, O-RAN testing with Titan
Goto Forum:
  


Current Time: Sun Jul 13 12:20:08 EDT 2025

Powered by FUDForum. Page generated in 0.06500 seconds
.:: Contact :: Home ::.

Powered by: FUDforum 3.0.2.
Copyright ©2001-2010 FUDforum Bulletin Board Software

Back to the top

Sign up to our Newsletter

A fresh new issue delivered monthly