Asterisk Ending Call after Answering ( around 30 seconds)

Asterisk Asterisk SIP
1

we are using Asterisk 20.9.3. Asterisk has 3 Kamailio proxy , which is given in PJSIP config

outbound_proxy=sip:sipcore.region.uat.domain:4060;lr

So outbound call to Registered device through Core1 is failing getting a 408 request back.
Astersik is trying with Core2 with same callId and increased Cseq number. It is getting response and eventually agent answer the call.
But after exactly 32 seconds of initial invite Asterisk is Ending the Call.
Checked Full log didn’t find anything unusual rather than
app.c: Message ended by control

Do you guys know why asterisk is ending the call. It happen only if I am getting 408 through one proxy , and success through another one.

1 Like
2

You haven’t provided any SIP trace so one can only guess that an ACK from the remote side was not received, and thus call ended at 32 seconds when the timer ran out.

3

This is the siptrace

4

image

5

Media is Asterisk Instance.

6

I would prefer a trace from Asterisk itself, because that shows what Asterisk sees.

7

And ideally an actual Asterisk log.

8

asteriskLog.txt (96.6 KB)

here is the log from asterisk with PJSIP set logger on.

9

I added the log you asked if anything you need please ask. Thank you.

10

There are two BYE requests going out. Which one is unexpected to you?

11

with CallId 3179e3c3-4f9d-46f3-9c59-d87f56246484 is un expected call (B-leg) other one is A leg of the same dialog.

12

Nothing is evident within the SIP signaling. Have you looked at the ARI application and what commands it is invoking?

13

Apparenlty we are doing anything suspecious here. After stasis get Answer event it complete the processing by 2025-07-15 14:45:48.404

Then the next event is Stasis End

2025-07-15 14:46:11.098 +00:00: {"level":"info","message":"CLaVd9z9ZMuhA4EFZgE0GKV","metadata":{"eventName":"stasisEndEvent","event":{"type":"StasisEnd","timestamp":"2025-07-15T14:46:11.096+0000","channel":{"id":"CHVqUwsNd3Vvjxs6dL0PxwG","name":"PJSIP/sipcore-00000a9f","state":"Up","protocol_id":"3179e3c3-4f9d-46f3-9c59-d87f56246484","caller":{"name":"","number":""},"connected":{"name":"+1651232007@dummy-kamailio-pstn.com","number":"+1650xxxx007"},"accountcode":"","dialplan":{"context":"internal","exten":"s","priority":1,"app_name":"Stasis","app_data":"stasis-bifrost,incomingDialed"},"creationtime":"2025-07-15T14:45:37.099+0000","language":"en"},"asterisk_id":"0e:7c:1a:bb:4d:bb","application":"stasis-bifrost"}},"timestamp":"2025-07-15 14:46:11"}

So ARI application is hangup the A leg.

note that there is no issue with the call if it is not Getting 408 Response from one of our proxy.

As you can see in the sip trace we have a 408 for the initial invite. So is there any way that might causing the issue?

Also in Ari logs we are not aware of 408 request time out. We are getting for that channel , dial empty, dial Ringing , and dial Answer Event.
Then stasisEnd.

14

I tried to reproduce it many times the pattern found is

  1. Asterisk Ending the call around 30-33 seconds after initial invite.
  2. Issue happen only for Invite getting 408 response through initial Core.
  3. For calls without 408 response No issue , Call can go extended period of time.

SIP RFC dictates a Timer
Timer B 64*T1 17.1.1.2 INVITE transaction timeout timer

Does this have to do anything with this case?

15

You showed a single ARI event, but didn’t show anything the ARI application may have done. I can only go based on your own analysis/bits of information, so I can’t answer anything further. Maybe if you also got an Asterisk debug log[1] it would show something further.

[1] Collecting Debug Information - Asterisk Documentation

16

debugLogAstersisk.txt (117.1 KB)

here is the debug log you asked for. @jcolp

17

I really really think you should look at the ARI commands coming from your ARI application to Asterisk. There are things in the debug log which are making me question whether you are deleting the bridge for example with the channels in it, that then causes them to hang up.

18 
[2025-07-16 11:06:45.822] DEBUG[1973289] res_pjsip_session.c:  Setting media session as default for audio
[2025-07-16 11:06:45.822] DEBUG[1973289] res_pjsip_session.c:  Done
[2025-07-16 11:06:45.822] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Stream: 0:audio-0:audio:sendrecv (ulaw)
[2025-07-16 11:06:45.822] DEBUG[1973289] res_pjsip_sdp_rtp.c:  PJSIP/sipcore-0000001e Type: audio 0:audio-0:audio:sendrecv (ulaw)
[2025-07-16 11:06:45.822] DEBUG[1973289] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 172.29.40.33: Using it for RTP media.
[2025-07-16 11:06:45.822] DEBUG[1973289] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f353c0a11b0'
[2025-07-16 11:06:45.822] DEBUG[1973289] res_rtp_asterisk.c: (0x7f353c0a11b0) RTP allocated port 41946
[2025-07-16 11:06:45.822] DEBUG[1973289] rtp_engine.c: RTP instance '0x7f353c0a11b0' is setup and ready to go
[2025-07-16 11:06:45.823] DEBUG[1973289] res_rtp_asterisk.c: () RTCP setup on RTP instance
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_sdp_rtp.c:  RC: 1
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  Handled
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Event: TSX_STATE  Inv State: CALLING
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Calling  Inv State: CALLING
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Calling  Inv State: CALLING
[2025-07-16 11:06:45.823] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.823] DEBUG[1973289] chan_pjsip.c:  RC: 0
[2025-07-16 11:06:45.823] DEBUG[1988332] http.c: HTTP keeping session open.  status_code:200
[2025-07-16 11:06:45.824] VERBOSE[1988334] dial.c: Called sipcore/sip:af169b151d3b4b1fbbc59d08feec3305@uat-metrowest.csiq.io
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001e Method: INVITE Status: 100
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Proceeding  Inv State: CALLING
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Proceeding  Inv State: CALLING
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001d Method: INVITE Status: 100
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  408
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001d TSX State: Proceeding  Inv State: CALLING
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  PJSIP/sipcore-0000001d TSX State: Proceeding  Inv State: CALLING
[2025-07-16 11:06:45.825] DEBUG[1984401] res_pjsip_session.c:  
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d Method: INVITE Status: 180
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d Event: TSX_STATE  Inv State: EARLY
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d TSX State: Proceeding  Inv State: EARLY
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d TSX State: Proceeding  Inv State: EARLY
[2025-07-16 11:06:45.919] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:45.919] VERBOSE[1988333] dial.c: PJSIP/sipcore-0000001d is ringing
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d Method: INVITE Status: 480
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d Event: TSX_STATE  Inv State: DISCONNECTED
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d TSX State: Completed  Inv State: DISCONNECTED
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  Disconnected
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  (null session) TSX State: Completed  Inv State: DISCONNECTED
[2025-07-16 11:06:46.088] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:46.088] DEBUG[1973289] chan_pjsip.c:  PJSIP/sipcore-0000001d
[2025-07-16 11:06:46.088] DEBUG[1973289] chan_pjsip.c:  
[2025-07-16 11:06:46.089] DEBUG[1988333] channel.c: Channel 0x55c46692cfd0 'PJSIP/sipcore-0000001d' hanging up.  Refs: 2
[2025-07-16 11:06:46.089] DEBUG[1988333] chan_pjsip.c:  PJSIP/sipcore-0000001d
[2025-07-16 11:06:46.089] DEBUG[1988333] chan_pjsip.c:  Cause: 480
[2025-07-16 11:06:46.089] DEBUG[1973289] chan_pjsip.c:  PJSIP/sipcore-0000001d
[2025-07-16 11:06:46.089] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001d Response 480
[2025-07-16 11:06:46.089] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:46.089] DEBUG[1973280] cdr.c: Finalized CDR for PJSIP/sipcore-0000001d - start 1752664005.818906 answer 0.000000 end 1752664006.089025 dur 0.270 bill 1752664006.089 dispo NO ANSWER
[2025-07-16 11:06:46.089] DEBUG[1973289] res_rtp_asterisk.c: () RTP Stop
[2025-07-16 11:06:46.089] DEBUG[1973289] rtp_engine.c: Destroyed RTP instance '0x7f353c3a9330'
[2025-07-16 11:06:46.089] DEBUG[1973289] channel.c: Channel 0x55c46692cfd0 'PJSIP/sipcore-0000001d' destroying
[2025-07-16 11:06:46.089] DEBUG[1973289] chan_pjsip.c:  
[2025-07-16 11:06:46.089] DEBUG[1973280] cdr.c: Skipping CDR for PJSIP/sipcore-0000001d since we weren't answered
[2025-07-16 11:06:46.089] DEBUG[1973338] stasis.c: Topic 'channel:CHvhRGyZrS5Khfs5mjhl8gO': 0x55c4662b13a0 destroyed
[2025-07-16 11:06:46.307] VERBOSE[1988326][C-0000000d] res_rtp_asterisk.c: 0x7f353c092770 -- Strict RTP switching to RTP target address 172.29.11.176:36600 as source
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Method: INVITE Status: 408
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Event: TSX_STATE  Inv State: DISCONNECTED
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Calling  Inv State: CALLING
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Calling  Inv State: CALLING
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Completed  Inv State: CALLING
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  Nothing delayed
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e TSX State: Completed  Inv State: CALLING
[2025-07-16 11:06:47.791] DEBUG[1973289] res_pjsip_session.c:  
[2025-07-16 11:06:47.796] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Method: INVITE Status: 100

So I can see a 480 request coming for initial invite, and Asterisk is ending the first dial.
PJSIP/sipcore-0000001d for this channel.
When 408 response coming back Asterisk taking this as for the second Invite
PJSIP/sipcore-0000001e

For this channel There is a 408 then there is 100 trying with 180 ringing and Answer.
Further when asterisk ending the call , Log says Cause 408

[2025-07-16 11:07:19.793] DEBUG[1988334] bridge.c: Waiting for 0x7f353800c200(PJSIP/sipcore-0000001e) bridge thread to die.
[2025-07-16 11:07:19.793] DEBUG[1988334] channel.c: Channel 0x7f353000a230 'PJSIP/sipcore-0000001e' hanging up.  Refs: 2
[2025-07-16 11:07:19.793] DEBUG[1988334] chan_pjsip.c:  PJSIP/sipcore-0000001e
[2025-07-16 11:07:19.793] DEBUG[1988334] chan_pjsip.c:  Cause: 408
[2025-07-16 11:07:19.793] DEBUG[1973280] cdr.c: Finalized CDR for PJSIP/sipcore-0000001c - start 1752664005.673021 answer 1752664005.780508 end 1752664039.792782 dur 34.119 bill 34.012 dispo ANSWERED
[2025-07-16 11:07:19.794] DEBUG[1973289] chan_pjsip.c:  PJSIP/sipcore-0000001e
[2025-07-16 11:07:19.794] DEBUG[1973289] res_pjsip_session.c:  PJSIP/sipcore-0000001e Response 408

Checked ARI Logic During call we are not deleting any bridges it happen only after ending the call.

19

I don’t have anything else to add, then, and if you decide to eventually file this as an issue you will need to provide a way to reproduce the issue. The issue won’t be accepted without that.

20

Hi so we put outbound proxy as a Round-robin DNS which mapped to 3 kamailio Proxy.

It goes through one proxy and got 408. Asterisk sending second invite through second proxy and got a 200 okay. but the channel in Asterisk is same. (i.e For the second invite Asterisk is calling on the same channel it tried in the initial invite)

So my question is this
What exactly you put in PJSIP outbound_proxy value.
Does this happen because we put a Round-robin DNS

@jcolp