[asterisk-dev] Asterisk / pjsip: Bug or feature? TCP/TLS connection is endless after unregistering the last trunk to the destination

Mon Jan 11 08:21:00 CST 2021

Hello!

I'm analyzing the transports opened by or for a Registration to an ISPs trunk. Here: transport type flow.

I can reproducibly see, that on Asterisk start up are always two connections created to register a trunk. The first one looks like this:

# grep "tlsc0x7fa1d82efae8" /var/log/asterisk/full
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d82efae8 TLS client transport created
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d82efae8 TLS transport 192.168.122.174:54761 is connecting to secure.sip.easybell.de:5061...
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d82efae8' state:CONNECTED
[2021-01-11 13:21:24] DEBUG[8569] pjproject:        tlsc0x7fa1d82efae8 TLS transport 192.168.122.174:54761 is connected to secure.sip.easybell.de:5061

=> this one gets never used - you can see there only tls keep alives.

The second one is the one used:
# grep "tlsc0x7fa1d8324ec8" /var/log/asterisk/full
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d8324ec8 .TLS client transport created
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d8324ec8 .TLS transport 192.168.122.174:48650 is connecting to secure.sip.easybell.de:5061...
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d8324ec8' state:CONNECTED
[2021-01-11 13:21:24] DEBUG[8569] pjproject:        tlsc0x7fa1d8324ec8 TLS transport 192.168.122.174:48650 is connected to secure.sip.easybell.de:5061
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d8008fe8) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:22:44] DEBUG[8621] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0000f08) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:24:04] DEBUG[8646] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0000e78) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:25:24] DEBUG[8654] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0003558) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:26:44] DEBUG[8667] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0000ed8) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:28:04] DEBUG[8674] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0001a28) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:29:24] DEBUG[8685] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0003498) to transport tlsc0x7fa1d8324ec8
[2021-01-11 13:30:44] DEBUG[8695] res_pjsip/pjsip_transport_events.c: Registered monitor 0x7fa219fca1cb(0x7fa1d0003228) to transport tlsc0x7fa1d8324ec8

It differs in the log output already at the beginning:
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d82efae8 TLS client transport created
vs
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d8324ec8 .TLS client transport created
								       ^
What does this dot mean? Where is it coming from?

It is possible to tcpkill the first connection without being restarted:

# tcpkill -i eth0 tcp port 54761
[2021-01-11 14:42:15] DEBUG[8569] pjproject:        tlsc0x7fa1d82efae8 TLS connection closed
[2021-01-11 14:42:15] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d82efae8' state:DISCONNECTED
[2021-01-11 14:42:15] DEBUG[8569] pjproject:           sip_transport.c Transport tlsc0x7fa1d82efae8 shutting down, force=0
[2021-01-11 14:42:15] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d82efae8' state:SHUTDOWN
[2021-01-11 14:42:15] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d82efae8' state:DESTROY
[2021-01-11 14:42:15] DEBUG[8569] pjproject:        tlsc0x7fa1d82efae8 TLS transport destroyed with reason 120104: Connection reset by peer

If you're doing the same against Telekom, they drop the first connect after 10 s (therefore no tcpkill is necessary)

Any idea why there are 2 connections started though only one is necessary? This is really odd.

Putting it all together of what can be seen in the logfile:
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Outbound REGISTER attempt 1 to 'sips:secure.sip.easybell.de' with client
'sips:004912345678912 at secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target 'secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: Transport type for target 'secure.sip.easybell.de' is 'TLS transport'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Created resolution tracking for target 'secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Added target 'secure.sip.easybell.de' with record type '35', transport 'TLS transport', and
port '5061'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Added target '_sips._tcp.secure.sip.easybell.de' with record type '33', transport 'TLS
transport', and port '5061'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Added target 'secure.sip.easybell.de' with record type '1', transport 'TLS transport', and
port '5061'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Starting initial resolution using parallel queries for target 'secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8580] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] All parallel queries completed
[2021-01-11 13:21:24] DEBUG[8580] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] A record received on target 'secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8580] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Resolution completed - 1 viable targets
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Address '0' is 212.172.58.207:5061 with transport 'TLS transport'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip/pjsip_resolver.c: [0x7fa1d800cbb8] Invoking user callback with '1' addresses
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d82efae8 TLS client transport created
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d82efae8 TLS transport 192.168.122.174:54761 is connecting to secure.sip.easybell.de:5061...
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d82efae8' state:CONNECTED
[2021-01-11 13:21:24] DEBUG[8569] pjproject:        tlsc0x7fa1d82efae8 TLS transport 192.168.122.174:54761 is connected to secure.sip.easybell.de:5061
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 401/REGISTER/cseq=43594 (rdata0x7fa1d82efdd8).  Using request
transaction as basis.
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa1d800be48 for Response msg 401/REGISTER/cseq=43594 (rdata0x7fa1d82efdd8).
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outreg/easybellPJSIP-00000063 on transaction tsx0x7fa1d800be48
[2021-01-11 13:21:24] DEBUG[8570] pjproject:         sip_auth_client.c ...Unable to set auth for tdta0x7fa1d8009e88: can not find credential for secure.sip.easybell.de/Digest
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Received REGISTER response 401(Unauthorized)
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Processing REGISTER response 401 from server 'sips:secure.sip.easybell.de' for client
'sips:004912345678912 at secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Sending authenticated REGISTER to server 'sips:secure.sip.easybell.de' from client
'sips:004912345678912 at secure.sip.easybell.de'

[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d8324ec8 .TLS client transport created
[2021-01-11 13:21:24] DEBUG[8570] pjproject:        tlsc0x7fa1d8324ec8 .TLS transport 192.168.122.174:48650 is connecting to secure.sip.easybell.de:5061...
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_transport_events.c: Reliable transport 'tlsc0x7fa1d8324ec8' state:CONNECTED
[2021-01-11 13:21:24] DEBUG[8569] pjproject:        tlsc0x7fa1d8324ec8 TLS transport 192.168.122.174:48650 is connected to secure.sip.easybell.de:5061

[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/REGISTER/cseq=43595 (rdata0x7fa1d83251b8).  Using request
transaction as basis.
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa1d8322ed8 for Response msg 200/REGISTER/cseq=43595 (rdata0x7fa1d83251b8).
[2021-01-11 13:21:24] DEBUG[8569] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outreg/easybellPJSIP-00000063 on transaction tsx0x7fa1d8322ed8
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Received REGISTER response 200(OK)
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Processing REGISTER response 200 from server 'sips:secure.sip.easybell.de' for client
'sips:004912345678912 at secure.sip.easybell.de'
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Outbound registration to 'sips:secure.sip.easybell.de' with client
'sips:004912345678912 at secure.sip.easybell.de' successful
[2021-01-11 13:21:24] DEBUG[8570] res_pjsip_outbound_registration.c: Scheduling outbound registration to server 'sips:secure.sip.easybell.de' from client
'sips:004912345678912 at secure.sip.easybell.de' in 80 seconds

It seems, that the first register is done through the first connection - all following registers are done by the second connection (can be seen in the tcpdump trace).
Things would be much more analyzable btw, if asterisk pcap trace would contain the local port of the connection, too - or if it would tell, which connection it is using.

Thanks
Michael