[asterisk-bugs] [JIRA] (ASTERISK-24414) TCP connection state is processed before the SIP response hits the transaction layer

[John Bigelow (JIRA)]

     [ https://issues.asterisk.org/jira/browse/ASTERISK-24414?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

John Bigelow updated ASTERISK-24414:
------------------------------------

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

Full log is attached show 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}



  was:
A TCP connection state is processed before the SIP response hits the transaction layer.

Full log is attached show 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}




> TCP connection state is processed before the SIP response hits the transaction layer
> ------------------------------------------------------------------------------------
>
>                 Key: ASTERISK-24414
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-24414
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Resources/res_pjsip, Resources/res_pjsip_outbound_registration
>    Affects Versions: SVN, 13.0.0-beta2
>         Environment: Asterisk SVN branch 13 @ 425285, PJSIP
>            Reporter: John Bigelow
>
> As discussed with jcolp, a TCP connection state is processed before the SIP response hits the transaction layer.
> Full log is attached show 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}



--
This message was sent by Atlassian JIRA
(v6.2#6252)