Re: [Lksctp-developers] Problem with sctp_recvmsg. First message (SSN = 0) is repeatedly returned.

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

And... I appear to have found the problem!

Isn't it funny how sometimes just explaining a problem to somebody else
allows your mind to follow the right process to come to the answer
yourself.

The answer is of course in the flags.  My code was...

    struct sctp_sndrcvinfo sndrcvinfo;
    int flags;

    // Receive as many bytes as possible into our temp buffer.
    char *tmpbuf = (char*) malloc (maxlen);
    if (DEBUG) { printf ("Reading up to %d bytes on socket %d.\n",
maxlen, sd); }
    int len = sctp_recvmsg (sd, (void *) tmpbuf, maxlen, (struct
sockaddr *) NULL, 0, &sndrcvinfo, &flags);

I was passing in flags in order to get the return flags.  However, I
didn't realise that flags is also used for the INPUT flags as well!

I was not initializing flags.  So at some stage the MSG_PEEK bit must
have been gotten toggled.  Once that happened... the repeated message
return is the logical result!

How embarrassing!  Thanks for being such good listeners!

    J.

On Wed, 2012-12-05 at 11:44 +1300, Jonathan Couper-Smartt wrote:
> Hiya fellow SCTP fans,
> 
> 	I've got little SIGTRAN stack running, but I'm finding a problem that
> arises from time to time.  Sometimes when I start my program, the first
> message (SSN = 0) is repeatedly returned, and is never cleared from the
> input buffer.
> 
> 	It seems to be:
> 
> 	* I start the program first time, it works great.  Messages are
> received properly.
> 
> 	* I kill the program and restart.  This time, I receive the first
> message repeatedly.  Wireshark confirms that this message is only being
> sent once.  It is definitely a problem in the read, presumably not
> clearing the input buffer.
> 
>   	* I kill the program and restart, it nearly always works OK after the
> re-re-start.
> 
> 
> Here's what I get when it spins.  Note that the SSN and TSN never
> change.
> 
> Reading up to 1024 bytes on socket 5.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0000, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0c970587, cumtsn = 0x00000000.
>     00 00 00 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 87 05 97 0c 00 00 00 00 2e 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:42:06.137285 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:42:06.137419 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:42:06.137537 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:42:06.137640 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 2012-12-05 11:42:06.137721 [DBG]: Encoding SUA: [3/4]
> 2012-12-05 11:42:06.137866 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 5.
>     01 00 03 04 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:42:06.138105 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 5.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0000, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0c970587, cumtsn = 0x00000000.
>     00 00 00 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 87 05 97 0c 00 00 00 00 2e 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:42:06.638442 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:42:06.638521 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:42:06.638579 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:42:06.638630 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 2012-12-05 11:42:06.638668 [DBG]: Encoding SUA: [3/4]
> 2012-12-05 11:42:06.638736 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 5.
>     01 00 03 04 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:42:06.638891 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 5.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0000, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0c970587, cumtsn = 0x00000000.
>     00 00 00 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 87 05 97 0c 00 00 00 00 2e 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:42:07.139255 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:42:07.139345 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:42:07.139413 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:42:07.139473 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 2012-12-05 11:42:07.139520 [DBG]: Encoding SUA: [3/4]
> 2012-12-05 11:42:07.139597 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 5.
>     01 00 03 04 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:42:07.139758 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 5.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0000, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0c970587, cumtsn = 0x00000000.
>     00 00 00 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 87 05 97 0c 00 00 00 00 2e 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:42:07.640151 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:42:07.640283 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:42:07.640394 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:42:07.640494 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 2012-12-05 11:42:07.640571 [DBG]: Encoding SUA: [3/4]
> 2012-12-05 11:42:07.640690 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 5.
>     01 00 03 04 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 
> 
> 
> Here's what I get when it works:
> 
> 2012-12-05 11:39:15.265271 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 6.
>     01 00 03 01 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:39:15.265574 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 6.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0000, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0e6e792b, cumtsn = 0x00000000.
>     00 00 00 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 2b 79 6e 0e 00 00 00 00 03 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:39:15.265837 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:39:15.265937 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:39:15.266033 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:39:15.266111 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 2012-12-05 11:39:15.266175 [DBG]: Encoding SUA: [3/4]
> 2012-12-05 11:39:15.266257 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 6.
>     01 00 03 04 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:39:15.266502 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 6.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0001, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0e6e792c, cumtsn = 0x00000000.
>     00 00 01 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 2c 79 6e 0e 00 00 00 00 03 02 00 00
>     01 00 03 04 00 00 00 08
> 2012-12-05 11:39:15.766868 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:39:15.766947 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:39:15.767007 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 4, Length 8
> 2012-12-05 11:39:15.767065 [NTC]: SCCP #2 (itp): SUA Received ASPUP_ACK.
> Now waiting for NTFY.
> 2012-12-05 11:39:20.303896 [NTC]: SCCP #2 (itp): SUA Sending ASPUP
> request.
> 2012-12-05 11:39:20.303975 [DBG]: Encoding SUA: [3/1]
> 2012-12-05 11:39:20.304048 [DBG]: SCCP #2 (itp): Sending 8 bytes.
> Sending 8 bytes on socket 6.
>     01 00 03 01 00 00 00 08
> ...sent 8 bytes.
> _sctp_send: sctp_sendmsg ok 8 bytes.
> 2012-12-05 11:39:20.304238 [DBG]: SCCP #2 (itp): Sent OK
> Reading up to 1024 bytes on socket 6.
> _sctp_recv: sctp_recvmsg ok 8 bytes, flags = 0x00000080.
> _sctp_recv: stream = 0x0000, ssn = 0x0002, flags = 0x0000, ppid =
> 0x00000004.
> _sctp_recv: context = 0x00000000, tsn = 0x0e6e792d, cumtsn = 0x00000000.
>     00 00 02 00 00 00 ff ff 00 00 00 04 00 00 00 00
>     00 00 00 00 2d 79 6e 0e 00 00 00 00 03 02 00 00
>     01 00 03 01 00 00 00 08
> 2012-12-05 11:39:20.404896 [DBG]: SCCP #2 (itp): Received 8 bytes.
> 2012-12-05 11:39:20.405098 [DBG]: SCCP #2 (itp): SUA Decoding message of
> length 8
> 2012-12-05 11:39:20.405284 [DBG]: SCCP #2 (itp): SUA Version 1, Class 3,
> Type 1, Length 8
> 2012-12-05 11:39:20.405391 [NTC]: SCCP #2 (itp): SUA Received ASPUP.
> Send ACK.
> 
> 
>     I don't suppose anybody can throw me a clue?  Currently my plan is
> simply to detect the repeated SSN, and close and restart the connection
> again.  But really I'd love to help fix the problem properly!
> 
>     J.
> 
> 

-- 
Jonathan Couper-Smartt
General Manager, N-Squared Software
Office: (06) 358 1140
Mobile: (027) 733 9716
Jonathan Couper-Smartt
General Manager, N-Squared Software
Office: (06) 358 1140
Mobile: (027) 733 9716

Re: [Lksctp-developers] Problem with sctp_recvmsg. First message (SSN = 0) is repeatedly returned.

Re: [Lksctp-developers] Problem with sctp_recvmsg. First message (SSN = 0) is repeatedly returned. (SOLVED)