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 17:07  |
 Pau Espin Pedrol
Messages: 14
Registered: November 2021 |
Junior Member |
|
|
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 #1848284 is a reply to message #1848260] |
Fri, 26 November 2021 12:49  |
Pau Espin Pedrol
Messages: 14
Registered: November 2021 |
Junior Member |
|
|
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 12:50] Report message to a moderator |
|
| |
| 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 12:11 |
|
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 #1848681 is a reply to message #1848408] |
Mon, 13 December 2021 18:49 |
Pau Espin Pedrol
Messages: 14
Registered: November 2021 |
Junior Member |
|
|
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
|
|
| | | | |
Goto Forum:
Current Time: Mon Oct 14 02:50:34 GMT 2024
Powered by FUDForum. Page generated in 0.05135 seconds |
] 
Search
Help
Register
Login
Home
