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:004912345678...@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:004912345678...@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:004912345678...@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:004912345678...@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:004912345678...@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:004912345678...@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
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
asterisk-dev mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-dev
