Why doesn't Asterisk 17 catch hangup request from PJSIP client? [Solved]

Question

I am looking to replace my older Asterisk 15 VoIP Server with Asterisk 17. Currently I have an application that works with Asterisk over ARI (i.e. Asterisk Rest Interface) + WS (for events). On my current version everything works fine, but after conncting my app to Asterisk 17 it did not receive ChannelHangupRequest event and the following events in time (i.e. only after ~30 seconds). So I've decided to take a look on the Asterisk logs and I've found out that:

1. The problem is not caused by my app
2. The ChannelHangupRequest event is send, as I said before, after about 30-50 seconds. The interesting part is that it's cause is equal to 1 and there is a field soft equal to true. You can see below the event in JSON format. Official Asterisk 17 documentation does not give an obvious description for it or at least it is not obvious to me: From soft: boolean (optional) - Whether the hangup request was a soft hangup request. Also, official hangup cause mappings indicate that 1 is mapped to AST_CAUSE_UNALLOCATED. On my older version (i.e. Asterisk 15), where the event fires immediately, case is equal to 16 = AST_CAUSE_NORMAL_CLEARING.

<{"cause":1,"soft":true,"type":"ChannelHangupRequest","timestamp":"2021-03-23T17:10:19.817+0000","channel":{"id":"1616519370.38","name":"PJSIP/1000-00000026","state":"Up","caller":{"name":"Cristi","number":"1000"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"from-internal","exten":"s","priority":1,"app_name":"Stasis","app_data":"my-app"},"creationtime":"2021-03-23T17:09:30.364+0000","language":"en"},"asterisk_id":"02:42:ac:13:00:03","application":"my-app"} < {"type":"StasisEnd","timestamp":"2021-03-23T17:10:19.817+0000","channel":{"id":"1616519370.38","name":"PJSIP/1000-00000026","state":"Up","caller":{"name":"Cristi","number":"1000"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"from-internal","exten":"s","priority":1,"app_name":"Stasis","app_data":"my-app"},"creationtime":"2021-03-23T17:09:30.364+0000","language":"en"},"asterisk_id":"02:42:ac:13:00:03","application":"my-app"}

3. Asterisk log shows that channel was disconnected for lack of audio RTP activity in 49 seconds. It explains the behaviour to some extent, specifically, it explains where the ChannelHangupRequest event comes from (after ~50 seconds), but it does not explain why isn't it sent properly immediately after user hangups.

13373[2021-03-23 17:09:28] VERBOSE[6273] stasis/app.c: Creating Stasis app 'my-app' 13374[2021-03-23 17:09:28] VERBOSE[6273] res_http_websocket.c: WebSocket connection from '172.19.0.1:54308' for protocol '' accepted using version '13' 13375[2021-03-23 17:09:29] VERBOSE[6276] stasis/app.c: Replacing Stasis app 'my-app' 13376[2021-03-23 17:09:29] VERBOSE[6276] res_http_websocket.c: WebSocket connection from '172.19.0.1:54312' for protocol '' accepted using version '13' 13377[2021-03-23 17:09:30] VERBOSE[6278] stasis/app.c: Replacing Stasis app 'my-app' 13378[2021-03-23 17:09:30] VERBOSE[6278] res_http_websocket.c: WebSocket connection from '172.19.0.1:54322' for protocol '' accepted using version '13' 13379[2021-03-23 17:09:30] VERBOSE[6280] dial.c: Called 1000 13380[2021-03-23 17:09:30] VERBOSE[1601] netsock2.c: Using SIP RTP Audio TOS bits 184 13381[2021-03-23 17:09:30] VERBOSE[1601] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field. 13382[2021-03-23 17:09:30] VERBOSE[1601] netsock2.c: Using SIP RTP Audio CoS mark 5 13383[2021-03-23 17:09:30] VERBOSE[6280] dial.c: PJSIP/1000-00000026 is ringing 13384[2021-03-23 17:09:30] VERBOSE[6280] dial.c: PJSIP/1000-00000026 is ringing 13385[2021-03-23 17:09:44] VERBOSE[6276] res_http_websocket.c: WebSocket connection from '172.19.0.1:54312' closed 13386[2021-03-23 17:09:45] VERBOSE[6282] stasis/app.c: Replacing Stasis app 'my-app' 13387[2021-03-23 17:09:45] VERBOSE[6282] res_http_websocket.c: WebSocket connection from '172.19.0.1:54334' for protocol '' accepted using version '13' 13388[2021-03-23 17:09:49] VERBOSE[1601] res_rtp_asterisk.c: 0x7f8c1c02bf90 -- Strict RTP learning after remote address set to: 192.168.10.172:10096 13389[2021-03-23 17:09:49] VERBOSE[6280] dial.c: PJSIP/1000-00000026 answered 13390[2021-03-23 17:09:49] WARNING[1601] channel.c: Unable to find a codec translation path: (ulaw) -> (g723) 13391[2021-03-23 17:09:49] WARNING[1601] channel.c: Unable to find a codec translation path: (g723) -> (ulaw) 13392[2021-03-23 17:09:49] VERBOSE[6280] ari/resource_channels.c: Launching Stasis(my-app) on PJSIP/1000-00000026 13393[2021-03-23 17:10:19] NOTICE[1108] res_pjsip_sdp_rtp.c: Disconnecting channel 'PJSIP/1000-00000026' for lack of audio RTP activity in 49 seconds

4. The above described behaviour applies only when user answers and, then, drops. If the user rejects call without answering, everything works fine.

One solution would be to reduce the RTP inactivity timeout as a workaround, but this wouldn't be preferable. Do you have any suggestions?

Answer 1

Solved. The problem was in my firewall configuration. The testing environment was not properly configured, thus some packets were dropped before reaching to Asterisk. So, there wasn't a problem with Asterisk itself.