ASTERISK-24414: TCP connection state is processed before the SIP response hits the transaction layer

[Home]

Summary: ASTERISK-24414: TCP connection state is processed before the SIP response hits the transaction layer

Reporter: John Bigelow (jbigelow) Labels:

Date Opened: 2014-10-13 13:07:13 Date Closed:

Priority: Major Regression?

Status: Open/New Components: Resources/res_pjsip Resources/res_pjsip_outbound_registration

Versions: SVN 13.0.0-beta2 Frequency of
Occurrence Frequent

Related
Issues:

Environment: Asterisk SVN branch 13 @ 425285, PJSIP Attachments: ( 0) full.txt

Description: As discussed with jcolp, a TCP connection state is processed before the SIP response hits the transaction layer.

The attached full log shows outbound registrations that register and then are immediately unregistered. Note: The patch on ASTERISK-24411 is applied but does not impact this issue. Additionally I've add warning messages to simply log the response code and result of whether or not the response status is in the 200 code class.

Snippet of full log:
{noformat}
[Oct 13 10:56:14] DEBUG[15242] res_pjsip_outbound_registration.c: REGISTER attempt 1 to 'sip:ua-ipv6-tcp@[::1]:5061;transport=tcp' with client 'sip:ua-ipv6-tcp@[::1]:5060;transport=tcp'
[Oct 13 10:56:14] DEBUG[15242] pjsip: tcpc0xb317c954 .TCP client transport created
[Oct 13 10:56:14] DEBUG[15242] pjsip: tcpc0xb317c954 .TCP transport ::1:50777 is connecting to ::1:5061...
[Oct 13 10:56:14] VERBOSE[15242] res_pjsip_logger.c: <--- Transmitting SIP request (513 bytes) to TCP:::1:5061 --->
REGISTER sip:ua-ipv6-tcp@[::1]:5061;transport=tcp SIP/2.0
Via: SIP/2.0/TCP [::1]:5060;rport;branch=z9hG4bKPj24635a48-f3ac-4689-9dbb-9e99bd2c6e71;alias
From: <sip:ua-ipv6-tcp@[::1]>;tag=25fe9ce2-05e1-4b3b-9305-fdf3a919b7b7
To: <sip:ua-ipv6-tcp@[::1]>
Call-ID: fd63e184-b584-43fe-88bf-8aec6f07ceae
CSeq: 64827 REGISTER
Contact: <sip:s@[::1]:5060;transport=TCP>
Expires: 300
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Content-Length: 0

[Oct 13 10:56:14] DEBUG[15247] pjsip: tcpc0xb317c954 TCP transport ::1:50777 is connected to ::1:5061
[Oct 13 10:56:14] VERBOSE[15247] res_pjsip_logger.c: <--- Received SIP response (380 bytes) from TCP:::1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP [::1]:5060;rport;branch=z9hG4bKPj24635a48-f3ac-4689-9dbb-9e99bd2c6e71;alias
From: <sip:ua-ipv6-tcp@[::1]>;tag=25fe9ce2-05e1-4b3b-9305-fdf3a919b7b7
To: <sip:ua-ipv6-tcp@[::1]>;tag=15346SIPpTag011
Call-ID: fd63e184-b584-43fe-88bf-8aec6f07ceae
CSeq: 64827 REGISTER
Expires: 300
Contact: <sip:[::1]:5061;transport=TCP>
Content-Length: 0

[Oct 13 10:56:14] WARNING[15242] res_pjsip_outbound_registration.c: RESPONSE CODE: '200'
[Oct 13 10:56:14] WARNING[15242] res_pjsip_outbound_registration.c: STATUS IN CLASS: '1'
[Oct 13 10:56:14] DEBUG[15242] res_pjsip_outbound_registration.c: Outbound registration to 'sip:ua-ipv6-tcp@[::1]:5061;transport=tcp' with client 'sip:ua-ipv6-tcp@[::1]:5060;transport=tcp' successful
[Oct 13 10:56:14] DEBUG[15319] manager.c: Examining AMI event:
Event: Registry
Privilege: system,all
ChannelType: PJSIP
Username: sip:ua-ipv6-tcp@[::1]:5060;transport=tcp
Domain: sip:ua-ipv6-tcp@[::1]:5061;transport=tcp
Status: Registered

[Oct 13 10:56:14] DEBUG[15319] manager.c: Running action 'PJSIPUnregister'
[Oct 13 10:56:14] VERBOSE[15242] res_pjsip_logger.c: <--- Transmitting SIP request (400 bytes) to TCP:::1:5061 --->
REGISTER sip:ua-ipv6-tcp@[::1]:5061;transport=tcp SIP/2.0
Via: SIP/2.0/TCP [::1]:5060;rport;branch=z9hG4bKPj5c93fca5-01f7-49e0-9dc1-bf9ef3a370d1;alias
From: <sip:ua-ipv6-tcp@[::1]>;tag=85be1bab-c91b-4afc-8c83-5866dadfad17
To: <sip:ua-ipv6-tcp@[::1]>
Call-ID: fd63e184-b584-43fe-88bf-8aec6f07ceae
CSeq: 64828 REGISTER
Contact: <sip:s@[::1]:5060;transport=TCP>
Expires: 0
Content-Length: 0

[Oct 13 10:56:14] VERBOSE[15247] res_pjsip_logger.c: <--- Received SIP response (378 bytes) from TCP:::1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP [::1]:5060;rport;branch=z9hG4bKPj5c93fca5-01f7-49e0-9dc1-bf9ef3a370d1;alias
From: <sip:ua-ipv6-tcp@[::1]>;tag=85be1bab-c91b-4afc-8c83-5866dadfad17
To: <sip:ua-ipv6-tcp@[::1]>;tag=15346SIPpTag011
Call-ID: fd63e184-b584-43fe-88bf-8aec6f07ceae
CSeq: 64828 REGISTER
Expires: 0
Contact: <sip:[::1]:5061;transport=TCP>
Content-Length: 0

[Oct 13 10:56:14] DEBUG[15247] pjsip: tcpc0xb317c954 TCP connection closed
[Oct 13 10:56:14] WARNING[15242] res_pjsip_outbound_registration.c: RESPONSE CODE: '503'
[Oct 13 10:56:14] WARNING[15242] res_pjsip_outbound_registration.c: STATUS IN CLASS: '0'
[Oct 13 10:56:14] WARNING[15242] res_pjsip_outbound_registration.c: Maximum retries reached when attempting outbound registration to 'sip:ua-ipv6-tcp@[::1]:5061;transport=tcp' with client 'sip:ua-ipv6-tcp@[::1]:5060;transport=tcp', stopping registration attempt
[Oct 13 10:56:14] DEBUG[15247] pjsip: tcpc0xb317c954 TCP transport destroyed with reason 70016: End of file (PJ_EEOF)
[Oct 13 10:56:14] DEBUG[15319] manager.c: Examining AMI event:
Event: Registry
Privilege: system,all
ChannelType: PJSIP
Username: sip:ua-ipv6-tcp@[::1]:5060;transport=tcp
Domain: sip:ua-ipv6-tcp@[::1]:5061;transport=tcp
Status: Rejected
{noformat}

Comments: By: John Bigelow (jbigelow) 2014-10-14 10:40:10.574-0500

*Note*: When resolved, the testsuite test corresponding to https://reviewboard.asterisk.org/r/4077/ needs to be updated to remove the pause at the end of the SIPp scenario.