sipsorcery icon indicating copy to clipboard operation
sipsorcery copied to clipboard

Published 20 hours ago • verified publisher icon sipsorcery-org

Softphone outgoing call Timeout

Open jvakos opened this issue 4 years ago • 4 comments

I get a timeout every time I try to place an outgoing call.

  • Incoming calls work as expected
  • Other softphones work for incoming and outgoing

Any thoughts how to investigate the issue?

[10:48:16 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on 0.0.0.0:5060. [10:48:16 DBG] CreateBoundUdpSocket successfully bound on 0.0.0.0:5060. [10:48:16 INF] SIP UDP Channel created for udp:0.0.0.0:5060. [10:48:16 INF] SIP TCP Channel created for tcp:0.0.0.0:5060. [10:48:16 DBG] SIP TCP Channel socket on tcp:0.0.0.0:5060 accept connections thread started. [10:48:16 DBG] Starting SIPRegistrationUserAgent for sip:[email protected], callback period 175s. [10:48:16 DBG] Starting registration for sip:[email protected]. [10:48:16 DBG] Initiating registration to voips-ng.modulus.gr at udp:185.73.42.250:5060 for sip:[email protected]. [10:48:17 DBG] Request Sent udp:172.17.2.6:5060<-udp:185.73.42.250:5060: REGISTER sip:voips-ng.modulus.gr SIP/2.0. [10:48:17 DBG] Response Received udp:0.0.0.0:5060<-udp:185.73.42.250:5060: REGISTER 401 Unauthorized. [10:48:17 DBG] Server response Unauthorised received for sip:[email protected]. [10:48:17 DBG] Request Sent udp:172.17.2.6:5060<-udp:185.73.42.250:5060: REGISTER sip:voips-ng.modulus.gr SIP/2.0. [10:48:17 DBG] Response Received udp:0.0.0.0:5060<-udp:185.73.42.250:5060: REGISTER 200 OK. [10:48:17 DBG] Server auth response Ok received for sip:[email protected]. [10:48:17 DBG] SIPRegistrationUserAgent was successful, scheduling next registration to sip:[email protected] in 133s. [10:48:38 DBG] calling sip:[email protected]. [10:48:38 DBG] Starting call to sip:[email protected]. [10:48:38 DBG] Call progressing, resolved sip:[email protected] to udp:185.73.42.250:5060. DNS lookup result for sip:[email protected]: udp:185.73.42.250:5060. [10:48:39 DBG] CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0. [10:48:39 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:0. [10:48:39 DBG] CreateBoundUdpSocket successfully bound on [::]:60238, dual mode True. [10:48:39 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:60239. [10:48:39 DBG] CreateBoundUdpSocket successfully bound on [::]:60239, dual mode True. [10:48:39 DBG] Successfully bound RTP socket [::]:60238 (dual mode True) and control socket [::]:60239 (dual mode True). [10:48:39 DBG] RTPChannel for [::]:60238 started. [10:48:39 DBG] SIPClientUserAgent attempting to resolve voips-ng.modulus.gr. [10:48:39 DBG] SIPClientUserAgent resolved voips-ng.modulus.gr to udp:185.73.42.250:5060 in 0,15ms. [10:48:39 DBG] UAC commencing call to sip:[email protected]:5060. [10:49:11 WRN] Call attempt to sip:[email protected] failed with TimedOut. [10:49:11 DBG] Call failed: TimedOut. [10:49:11 DBG] Ready

jvakos avatar Nov 11 '21 09:11 jvakos

You could try using the sipcmdline application to determine why you aren't getting a response.

examples\sipcmdline>dotnet run -- -d [email protected] -s uac -v

When I run the command above I do not get a response. It's possible that the provider is blocking requests based on username, IP address, non-registered user agent etc.

sipsorcery avatar Nov 11 '21 21:11 sipsorcery

Thank you for your fast reply. I run the above command and the results are the same as you described

....... [09:32:24 DBG] UAC commencing call to sip:[email protected]:5060. [09:32:25 DBG] Request retransmit 2 for request INVITE sip:[email protected] SIP/2.0, initial transmit 0,53s ago. [09:32:26 DBG] Request retransmit 3 for request INVITE sip:[email protected] SIP/2.0, initial transmit 1,545s ago. [09:32:28 DBG] Request retransmit 4 for request INVITE sip:[email protected] SIP/2.0, initial transmit 3,593s ago. [09:32:29 DBG] Cancelling forwarded call leg, sending CANCEL to sip:[email protected]. [09:32:29 WRN] Call attempt to sip:[email protected] failed with Call cancelled by user.. [09:32:29 WRN] sip:[email protected]:5060 Failed: Call cancelled by user. [09:32:30 WRN] => Request to sip:[email protected] did not get a response on task 1 after 5666ms. [09:32:30 DBG] Shutting down the SIP transport... [09:32:30 INF] => Command completed task count 1 success count 0 duration 5,68s.

It's possible that the provider is blocking requests based on username, IP address, non-registered user agent etc.

Registering & receiving calls work as expected so I suspect the last one: non-registered user agent . I'm building a softphone (that I will share when done) . The steps are

  1. I create a SIPTransport (shared with the below)
  2. I create a SIPRegistrationUserAgent for incoming calls
  3. after registration succeed I create a SIPUserAgent for outgoing calls.

I'm afraid that the SIPUserAgent is not "registered" because there is no connection between the two agents . Is this what you describe at "non-registered user agent".

This image is from wireshark using the sipcmdline image

This image is from wireshark using an other softphone image

jvakos avatar Nov 12 '21 07:11 jvakos

Try checking the Contact headers in your REGISTER and INVITE requests are the same. Some SIP providers have filtering rules in place to reject INVITEs if there is no curretn registration for the Contact header address.

sipsorcery avatar Nov 14 '21 13:11 sipsorcery

Sorry for late response. How can I set from sipsorcery side the Contact headers for REGISTER and INVITE ? I tried to find the requests with no luck. Here is my log.

17:10:52 DBG] Starting registration for sip:[email protected]. [17:10:52 DBG] Initiating registration to voips-ng.modulus.gr at udp:185.73.42.250:5060 for sip:[email protected]. [17:10:53 DBG] Request sent: udp:172.17.2.21:5060->udp:185.73.42.250:5060 REGISTER sip:voips-ng.modulus.gr SIP/2.0 [17:10:53 DBG] Response received: udp:0.0.0.0:5060<-udp:185.73.42.250:5060 REGISTER 401 Unauthorized [17:10:53 DBG] Server response Unauthorised received for sip:[email protected]. [17:10:53 DBG] Request sent: udp:172.17.2.21:5060->udp:185.73.42.250:5060 REGISTER sip:voips-ng.modulus.gr SIP/2.0 [17:10:53 DBG] Response received: udp:0.0.0.0:5060<-udp:185.73.42.250:5060 REGISTER 200 OK [17:10:53 DBG] Server auth response Ok received for sip:[email protected]. 23/12/2021 5:10:53 μμ Registration success [17:10:53 DBG] SIPRegistrationUserAgent was successful, scheduling next registration to sip:[email protected] in 235s. [17:11:11 DBG] RTPChannel closing, RTP receiver on port 64096, Control receiver on port 64097. Reason: . [17:11:13 DBG] CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0. [17:11:13 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:0. [17:11:13 DBG] CreateBoundUdpSocket even port required, closing socket on [::]:59615 and retrying on 59616. [17:11:13 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:59617. [17:11:13 DBG] CreateBoundUdpSocket successfully bound on [::]:59617, dual mode True. [17:11:13 DBG] Successfully bound RTP socket [::]:59616 (dual mode True) and control socket [::]:59617 (dual mode True). [17:11:13 DBG] RTPChannel for [::]:59616 started. Calling sip:[email protected] [17:11:13 DBG] SIPClientUserAgent attempting to resolve voips-ng.modulus.gr. [17:11:13 DBG] SIPClientUserAgent resolved voips-ng.modulus.gr to udp:185.73.42.250:5060 in 66,57ms. [17:11:13 DBG] UAC commencing call to sip:[email protected]:5060. [17:11:13 DBG] Request retransmit 2 for request INVITE sip:[email protected] SIP/2.0, initial transmit 0,505s ago. [17:11:14 DBG] Request retransmit 3 for request INVITE sip:[email protected] SIP/2.0, initial transmit 1,522s ago. [17:11:16 DBG] Request retransmit 4 for request INVITE sip:[email protected] SIP/2.0, initial transmit 3,546s ago. [17:11:20 DBG] Request retransmit 5 for request INVITE sip:[email protected] SIP/2.0, initial transmit 7,596s ago. [17:11:24 DBG] Request retransmit 6 for request INVITE sip:[email protected] SIP/2.0, initial transmit 11,599s ago. [17:11:28 DBG] Request retransmit 7 for request INVITE sip:[email protected] SIP/2.0, initial transmit 15,649s ago. [17:11:32 DBG] Request retransmit 8 for request INVITE sip:[email protected] SIP/2.0, initial transmit 19,651s ago. [17:11:36 DBG] Request retransmit 9 for request INVITE sip:[email protected] SIP/2.0, initial transmit 23,652s ago. [17:11:40 DBG] Request retransmit 10 for request INVITE sip:[email protected] SIP/2.0, initial transmit 27,7s ago. [17:11:44 DBG] Request retransmit 11 for request INVITE sip:[email protected] SIP/2.0, initial transmit 31,745s ago. [17:11:45 WRN] Call attempt to sip:[email protected] failed with TimedOut.

[17:14:48 DBG] Starting registration for sip:[email protected]. [17:14:48 DBG] Initiating registration to voips-ng.modulus.gr at udp:185.73.42.250:5060 for sip:[email protected]. [17:14:48 DBG] Request sent: udp:172.17.2.21:5060->udp:185.73.42.250:5060 REGISTER sip:voips-ng.modulus.gr SIP/2.0 [17:14:48 DBG] Response received: udp:0.0.0.0:5060<-udp:185.73.42.250:5060 REGISTER 401 Unauthorized [17:14:48 DBG] Server response Unauthorised received for sip:[email protected]. [17:14:48 DBG] Request sent: udp:172.17.2.21:5060->udp:185.73.42.250:5060 REGISTER sip:voips-ng.modulus.gr SIP/2.0 [17:14:48 DBG] Response received: udp:0.0.0.0:5060<-udp:185.73.42.250:5060 REGISTER 200 OK [17:14:48 DBG] Server auth response Ok received for sip:[email protected]. 23/12/2021 5:14:48 μμ Registration success [17:14:48 DBG] SIPRegistrationUserAgent was successful, scheduling next registration to sip:[email protected] in 196s. [17:15:22 DBG] RTPChannel closing, RTP receiver on port 59616, Control receiver on port 59617. Reason: . [17:16:34 DBG] CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0. [17:16:34 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:0. [17:16:34 DBG] CreateBoundUdpSocket even port required, closing socket on [::]:49303 and retrying on 49304. [17:16:34 DBG] CreateBoundUdpSocket attempting to create and bind UDP socket(s) on [::]:49305. [17:16:34 DBG] CreateBoundUdpSocket successfully bound on [::]:49305, dual mode True. [17:16:34 DBG] Successfully bound RTP socket [::]:49304 (dual mode True) and control socket [::]:49305 (dual mode True). [17:16:34 DBG] RTPChannel for [::]:49304 started. Calling sip:[email protected] [17:16:34 DBG] SIPClientUserAgent attempting to resolve voips-ng.modulus.gr. [17:16:34 DBG] SIPClientUserAgent resolved voips-ng.modulus.gr to udp:185.73.42.250:5060 in 69,07ms. [17:16:34 DBG] UAC commencing call to sip:[email protected]:5060. [17:16:35 DBG] Request retransmit 2 for request INVITE sip:[email protected] SIP/2.0, initial transmit 0,508s ago. [17:16:36 DBG] Request retransmit 3 for request INVITE sip:[email protected] SIP/2.0, initial transmit 1,52s ago. [17:16:38 DBG] Request retransmit 4 for request INVITE sip:[email protected] SIP/2.0, initial transmit 3,546s ago. [17:16:42 DBG] Request retransmit 5 for request INVITE sip:[email protected] SIP/2.0, initial transmit 7,594s ago. [17:16:46 DBG] Request retransmit 6 for request INVITE sip:[email protected] SIP/2.0, initial transmit 11,594s ago. [17:16:50 DBG] Request retransmit 7 for request INVITE sip:[email protected] SIP/2.0, initial transmit 15,595s ago. [17:16:54 DBG] Request retransmit 8 for request INVITE sip:[email protected] SIP/2.0, initial transmit 19,598s ago. [17:16:58 DBG] Request retransmit 9 for request INVITE sip:[email protected] SIP/2.0, initial transmit 23,601s ago. [17:17:02 DBG] Request retransmit 10 for request INVITE sip:[email protected] SIP/2.0, initial transmit 27,602s ago. [17:17:06 DBG] Request retransmit 11 for request INVITE sip:[email protected] SIP/2.0, initial transmit 31,65s ago. [17:17:06 WRN] Call attempt to sip:[email protected] failed with TimedOut.

I'm really sorry about asking again and again for the same problem. If I could solve the problem without bothering you i would have done it. Any directions will be very helpful.

jvakos avatar Dec 23 '21 15:12 jvakos