search

FreePBX / issue-tracker

The unified FreePBX issue tracker.
https://www.freepbx.org
GNU General Public License v3.0
9 stars 1 forks source link

[bug]: Call Flow Control "Feature Code" returning 488 error #180

Closed derekcrpd closed 4 months ago

derekcrpd commented 4 months ago

FreePBX Version

FreePBX 17

Issue Description

I am using a FreePBX17 install that is less than 1 week old. I have set a flow control and the BLF works as expected. However, when I push the button (which in fact sends the expected *280 to Asterisk), I receive a 488 error. I can manually change the status of the flow control through FreePBX, just not with my Grandstream phone using either the designated button, or the designated feature code. The set up is identical (I believe) to the setup I was using under FreePBX16 which worked fine.

I noticed this in the log: Using new stream 0:audio-0:audio:sendrecv (nothing) Out of an abundance of caution I tried removing my custom audio (set through System Recordings) and set it to "default"; however, same issue.

5-23-2024 9-30-01 AM

5-23-2024 9-30-01 AM

Operating Environment

FreePBX 17; Asterisk 21.0.2

+-------------------+------------+-----------------------------------+------------+-----------+ | Module | Version | Status | License | Signature | +-------------------+------------+-----------------------------------+------------+-----------+ | amd | 17.0.1 | Enabled | GPLv3+ | Sangoma | | announcement | 17.0.2.1 | Enabled | GPLv3+ | Sangoma | | api | 17.0.1.2 | Enabled | AGPLv3+ | Sangoma | | arimanager | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | asterisk-cli | 17.0.2 | Enabled | GPLv3+ | Sangoma | | asteriskinfo | 17.0.1 | Enabled | GPLv3+ | Sangoma | | backup | 17.0.5.29 | Enabled | GPLv3+ | Sangoma | | blacklist | 17.0.1.2 | Enabled | GPLv3+ | Sangoma | | builtin | | Enabled | | Unsigned | | bulkhandler | 17.0.4 | Enabled | GPLv3+ | Sangoma | | calendar | 17.0.4.13 | Enabled | GPLv3+ | Sangoma | | callback | 17.0.2.1 | Enabled | GPLv3+ | Sangoma | | callforward | 17.0.1.4 | Enabled | AGPLv3+ | Sangoma | | callrecording | 17.0.3.6 | Enabled | AGPLv3+ | Sangoma | | callwaiting | 17.0.3.3 | Enabled | GPLv3+ | Sangoma | | cdr | 17.0.4.13 | Enabled | GPLv3+ | Sangoma | | cel | 17.0.2.7 | Enabled | GPLv3+ | Sangoma | | certman | 17.0.3.10 | Enabled | AGPLv3+ | Sangoma | | cidlookup | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | conferences | 17.0.3.2 | Enabled | GPLv3+ | Sangoma | | configedit | 17.0.1.1 | Enabled | AGPLv3+ | Sangoma | | contactmanager | 17.0.5.9 | Enabled | GPLv3+ | Sangoma | | core | 17.0.9.57 | Enabled | GPLv3+ | Sangoma | | customappsreg | 17.0.1 | Enabled | GPLv3+ | Sangoma | | dashboard | 17.0.4.2 | Enabled | AGPLv3+ | Sangoma | | daynight | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | dictate | 17.0.1.2 | Enabled | GPLv3+ | Sangoma | | directory | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | donotdisturb | 17.0.2.2 | Enabled | GPLv3+ | Sangoma | | dynroute | 17.0.3 | Enabled | GPLv3+ | Sangoma | | extensionroutes | 17.0.1 | Enabled | Commercial | Sangoma | | extensionsettings | 17.0.1 | Enabled | GPLv3+ | Sangoma | | fax | 17.0.3.3 | Enabled | GPLv3+ | Sangoma | | featurecodeadmin | 17.0.2 | Enabled | GPLv3+ | Sangoma | | filestore | 17.0.2.12 | Enabled | AGPLv3 | Sangoma | | findmefollow | 17.0.4.7 | Enabled | GPLv3+ | Sangoma | | firewall | 17.0.1.25 | Enabled | AGPLv3+ | Sangoma | | framework | 17.0.15.22 | Enabled | GPLv2+ | Sangoma | | hotelwakeup | 17.0.1.6 | Enabled | GPLv2 | Sangoma | | iaxsettings | 17.0.1 | Enabled | AGPLv3 | Sangoma | | infoservices | 17.0.1 | Enabled | GPLv2+ | Sangoma | | ivr | 17.0.6 | Enabled | GPLv3+ | Sangoma | | languages | 17.0.1 | Enabled | GPLv3+ | Sangoma | | logfiles | 17.0.3.1 | Enabled | GPLv3+ | Sangoma | | manager | 17.0.5 | Enabled | GPLv2+ | Sangoma | | miscapps | 17.0.3 | Enabled | GPLv3+ | Sangoma | | miscdests | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | music | 17.0.4 | Enabled | GPLv3+ | Sangoma | | outroutemsg | 17.0.1 | Enabled | GPLv3+ | Sangoma | | paging | 17.0.3 | Enabled | GPLv3+ | Sangoma | | parking | 17.0.2.4 | Enabled | GPLv3+ | Sangoma | | phpinfo | 17.0.1 | Enabled | GPLv2+ | Sangoma | | pinsets | 17.0.3.2 | Enabled | GPLv3+ | Sangoma | | pm2 | 17.0.3.2 | Enabled | AGPLv3+ | Sangoma | | presencestate | 17.0.2.2 | Enabled | GPLv3+ | Sangoma | | printextensions | 17.0.1.2 | Enabled | GPLv3+ | Sangoma | | queueprio | 17.0.1.4 | Enabled | GPLv3+ | Sangoma | | queues | 17.0.1.9 | Enabled | GPLv2+ | Sangoma | | recordings | 17.0.2.2 | Enabled | GPLv3+ | Sangoma | | restapps | | Not Installed (Locally available) | Commercial | Sangoma | | ringgroups | 17.0.2.4 | Enabled | GPLv3+ | Sangoma | | sangomaconnect | | Not Installed (Locally available) | Commercial | Sangoma | | sangomartapi | | Not Installed (Locally available) | Commercial | Sangoma | | setcid | 17.0.1.2 | Enabled | GPLv3+ | Sangoma | | sipsettings | 17.0.6.7 | Enabled | AGPLv3+ | Sangoma | | sipstation | | Not Installed (Locally available) | Commercial | Sangoma | | smsplus | | Not Installed (Locally available) | Commercial | Sangoma | | soundlang | 17.0.4.1 | Enabled | GPLv3+ | Sangoma | | sysadmin | 17.0.1.83 | Enabled | Commercial | Sangoma | | timeconditions | 17.0.1.16 | Enabled | GPLv3+ | Sangoma | | tts | 17.0.1.1 | Enabled | GPLv3+ | Sangoma | | ttsengines | 17.0.1 | Enabled | AGPLv3 | Sangoma | | ucp | 17.0.4.15 | Enabled | AGPLv3+ | Sangoma | | userman | 17.0.6.22 | Enabled | AGPLv3+ | Sangoma | | vmblast | 17.0.2 | Enabled | GPLv3+ | Sangoma | | voicemail | 17.0.5.16 | Enabled | GPLv3+ | Sangoma | | voipinnovations | | Not Installed (Locally available) | Commercial | Sangoma | | weakpasswords | 17.0.1 | Enabled | GPLv3+ | Sangoma | | webrtc | 17.0.2.1 | Enabled | GPLv3+ | Sangoma | +-------------------+------------+-----------------------------------+------------+-----------+

Relevant log output

[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4300 session_on_rx_request:  (null session) Request: INVITE 
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4127 handle_new_invite_request:  Request: 
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003c to use for Request msg INVITE/cseq=141 (rdata0x7fcf982a5e68)
[2024-05-23 09:20:21] DEBUG[1046791]: chan_pjsip.c:2904 chan_pjsip_session_begin:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: chan_pjsip.c:2908 chan_pjsip_session_begin:  Direct media no glare mitigation
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:3976 new_invite:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4065 new_invite:  1000: Call (TLS:<<REDACTED>>:59667) to extension '*280' sending 100 Trying
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4591 handle_outgoing_response:  1000: Method is INVITE, Response is 100 Trying
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4610 handle_outgoing_response:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:21] DEBUG[1046791]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4707 session_inv_on_state_changed:  1000 Event: TSX_STATE  Inv State: INCOMING
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4459 __print_debug_details: The state change pertains to the endpoint '1000()'
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4464 __print_debug_details: The inv session still has an invite_tsx (0x7fcf5c3e56a8)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4479 __print_debug_details: There is no transaction involved in this state change
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is INCOMING
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4733 session_inv_on_state_changed: 1000: Source of transaction state change is TX_MSG
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4781 session_inv_on_state_changed:  
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed:  1000 TSX State: Proceeding  Inv State: INCOMING
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4459 __print_debug_details: The state change pertains to the endpoint '1000()'
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4464 __print_debug_details: The inv session still has an invite_tsx (0x7fcf5c3e56a8)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4470 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fcf5c3e56a8
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4474 __print_debug_details: The current transaction state is Proceeding
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is TX_MSG
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is INCOMING
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:5014 session_inv_on_tsx_state_changed:  Nothing delayed
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4245 session_on_tsx_state:  1000 TSX State: Proceeding  Inv State: INCOMING
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4249 session_on_tsx_state:  Topology: Pending: (null topology)  Active: (null topology)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4254 session_on_tsx_state:  
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:769 handle_incoming_sdp:  1000: Media count: 1
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:795 handle_incoming_sdp:  1000: Processing stream 0
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:832 handle_incoming_sdp:  1000: Using audio-0 for new stream name
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:876 handle_incoming_sdp:  1000: Using new stream 0:audio-0:audio:sendrecv (nothing)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:495 ast_sip_session_media_state_add:  1000 Adding position 0
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:541 ast_sip_session_media_state_add:  Creating new media session
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:584 ast_sip_session_media_state_add:  Setting media session as default for audio
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:589 ast_sip_session_media_state_add:  Done
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:929 handle_incoming_sdp:  1000: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_sdp_rtp.c:1501 negotiate_incoming_sdp_stream:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_sdp_rtp.c:1515 negotiate_incoming_sdp_stream:  Incompatible transport
[2024-05-23 09:20:21] ERROR[1046791]: res_pjsip_session.c:937 handle_incoming_sdp:  1000: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:937 handle_incoming_sdp:   1000: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:960 handle_incoming_sdp:  1000: Handled? no
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4591 handle_outgoing_response:  1000: Method is INVITE, Response is 488 Not Acceptable Here
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4610 handle_outgoing_response:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:21] DEBUG[1046791]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4707 session_inv_on_state_changed:  1000 Event: TSX_STATE  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4459 __print_debug_details: The state change pertains to the endpoint '1000()'
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4464 __print_debug_details: The inv session still has an invite_tsx (0x7fcf5c3e56a8)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4479 __print_debug_details: There is no transaction involved in this state change
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4733 session_inv_on_state_changed: 1000: Source of transaction state change is TX_MSG
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4781 session_inv_on_state_changed:  
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed:  1000 TSX State: Completed  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4459 __print_debug_details: The state change pertains to the endpoint '1000()'
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4464 __print_debug_details: The inv session still has an invite_tsx (0x7fcf5c3e56a8)
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4470 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fcf5c3e56a8
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4474 __print_debug_details: The current transaction state is Completed
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is TX_MSG
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4847 session_inv_on_tsx_state_changed:  Disconnected
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4245 session_on_tsx_state:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4254 session_on_tsx_state:  
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4110 new_invite:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4201 handle_new_invite_request:  Request:  Session: 1000
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:4319 session_on_rx_request:  (null session) Handled request INVITE  ? yes
[2024-05-23 09:20:21] DEBUG[1046791]: chan_pjsip.c:2925 chan_pjsip_session_end:  1000
[2024-05-23 09:20:21] DEBUG[1046791]: chan_pjsip.c:2928 chan_pjsip_session_end:  No channel
[2024-05-23 09:20:21] DEBUG[1046791]: res_pjsip_session.c:2912 session_destructor: 1000: Destroying SIP session
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7fcf78294158 for Request msg ACK/cseq=141 (rdata0x7fcf9821c9d8)
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003c to use for Request msg ACK/cseq=141 (rdata0x7fcf9821c9d8)
[2024-05-23 09:20:21] DEBUG[1037991]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:21] DEBUG[1037991]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_endpoint_identifier_ip.c:258 ip_identify_match_check: Source address <<REDACTED>>:59667 does not match identify '<<REDACTED>>'
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '1000' domain '<<REDACTED>>'
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '1000' domain '<<REDACTED>>'
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed:  (null session) TSX State: Confirmed  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4457 __print_debug_details: inv_session 0x7fcffc01ab38 has no ast session
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4464 __print_debug_details: The inv session still has an invite_tsx (0x7fcf5c3e56a8)
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4470 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fcf5c3e56a8
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4474 __print_debug_details: The current transaction state is Confirmed
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is RX_MSG
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4837 session_inv_on_tsx_state_changed:  Session ended
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4245 session_on_tsx_state:  (null session) TSX State: Confirmed  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[1037991]: res_pjsip_session.c:4254 session_on_tsx_state:  
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4445 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4457 __print_debug_details: inv_session 0x7fcffc01ab38 has no ast session
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4467 __print_debug_details: The inv session does NOT have an invite_tsx
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4470 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fcf5c3e56a8
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4474 __print_debug_details: The current transaction state is Terminated
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is TIMER
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is DISCONNCTD
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4837 session_inv_on_tsx_state_changed:  Session ended
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4245 session_on_tsx_state:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[2024-05-23 09:20:21] DEBUG[934543]: res_pjsip_session.c:4254 session_on_tsx_state:  
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR '<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact '<<REDACTED>>@@d68d42959d07a3a498260448b030cd70' on AOR '<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip.c:1716 endpt_send_request: 0x7fcf9c02ddf0: Wrapper created
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip.c:1731 endpt_send_request: 0x7fcf9c02ddf0: Set timer to 3000 msec
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '<<REDACTED>>.<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '<<REDACTED>>.<<REDACTED>>' is 'TLS transport'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_resolver.c:545 sip_resolve: [0x7fcf9c02ecf8] Created resolution tracking for target '<<REDACTED>>.<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_resolver.c:174 sip_resolve_add: [0x7fcf9c02ecf8] Added target '<<REDACTED>>.<<REDACTED>>' with record type '1', transport 'TLS transport', and port '5061'
[2024-05-23 09:20:23] DEBUG[1029883]: res_pjsip/pjsip_resolver.c:616 sip_resolve: [0x7fcf9c02ecf8] Starting initial resolution using parallel queries for target '<<REDACTED>>.<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[934556]: res_pjsip/pjsip_resolver.c:273 sip_resolve_callback: [0x7fcf9c02ecf8] All parallel queries completed
[2024-05-23 09:20:23] DEBUG[934556]: res_pjsip/pjsip_resolver.c:322 sip_resolve_callback: [0x7fcf9c02ecf8] A record received on target '<<REDACTED>>.<<REDACTED>>'
[2024-05-23 09:20:23] DEBUG[934556]: res_pjsip/pjsip_resolver.c:417 sip_resolve_callback: [0x7fcf9c02ecf8] Resolution completed - 1 viable targets
[2024-05-23 09:20:23] DEBUG[1046791]: res_pjsip/pjsip_resolver.c:199 sip_resolve_invoke_user_callback: [0x7fcf9c02ecf8] Address '0' is <<REDACTED>>:5061 with transport 'TLS transport'
[2024-05-23 09:20:23] DEBUG[1046791]: res_pjsip/pjsip_resolver.c:205 sip_resolve_invoke_user_callback: [0x7fcf9c02ecf8] Invoking user callback with '1' addresses
[2024-05-23 09:20:23] DEBUG[1046791]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to <<REDACTED>>:5061 (this may be re-written again later)
[2024-05-23 09:20:23] DEBUG[1046791]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:23] DEBUG[1046791]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:23] DEBUG[934543]: res_pjsip/pjsip_distributor.c:519 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=60760 (rdata0x7fcf782451f8).  Using request transaction as basis.
[2024-05-23 09:20:23] DEBUG[934543]: res_pjsip/pjsip_distributor.c:127 find_request_serializer: Found transaction tsx0x7fcf5c3e56a8 for Response msg 200/OPTIONS/cseq=60760 (rdata0x7fcf782451f8).
[2024-05-23 09:20:23] DEBUG[934543]: res_pjsip/pjsip_distributor.c:137 find_request_serializer: Found serializer pjsip/options/<<REDACTED>>-00000043 on transaction tsx0x7fcf5c3e56a8
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip.c:1594 endpt_send_request_cb: 0x7fcf9c02ddf0: PJSIP tsx response received
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip.c:1607 endpt_send_request_cb: 0x7fcf9c02ddf0: Cancelling timer
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip.c:1616 endpt_send_request_cb: 0x7fcf9c02ddf0: Timer cancelled
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip.c:1637 endpt_send_request_cb: 0x7fcf9c02ddf0: Callbacks executed
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x7fcf9c02ddf0: wrapper destroyed
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact <<REDACTED>>/sip:253878@<<REDACTED>>.<<REDACTED>>:5061 status didn't change: Reachable, RTT: 85.952 msec
[2024-05-23 09:20:23] DEBUG[1037991]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR '<<REDACTED>>' now has 1 available contacts
[2024-05-23 09:20:25] DEBUG[934557]: res_pjsip_registrar.c:1377 check_expiration_thread: Woke up at 1716470425  Interval: 30
[2024-05-23 09:20:25] DEBUG[934557]: res_pjsip_registrar.c:1384 check_expiration_thread: Expiring 0 contacts
[2024-05-23 09:20:30] DEBUG[934543]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg SUBSCRIBE/cseq=74220 (rdata0x7fcf9821c9d8)
[2024-05-23 09:20:30] DEBUG[934543]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000002b to use for Request msg SUBSCRIBE/cseq=74220 (rdata0x7fcf9821c9d8)
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:30] DEBUG[1029883]: res_pjsip_endpoint_identifier_ip.c:258 ip_identify_match_check: Source address <<REDACTED>>:59667 does not match identify '<<REDACTED>>'
[2024-05-23 09:20:30] DEBUG[1029883]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '1000' domain '<<REDACTED>>'
[2024-05-23 09:20:30] DEBUG[1029883]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '1000' domain '<<REDACTED>>'
[2024-05-23 09:20:30] DEBUG[1029883]: res_pjsip_authenticator_digest.c:471 digest_check_auth: Using default realm 'asterisk' on incoming auth '1000-auth'.
[2024-05-23 09:20:30] DEBUG[1029883]: res_pjsip_authenticator_digest.c:358 verify: Realm: asterisk  Username: 1000  Result: NOAUTH
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<<REDACTED>>' into...
[2024-05-23 09:20:30] DEBUG[1029883]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<<REDACTED>>' and port ''.
[2024-05-23 09:20:30] DEBUG[1064397]: manager.c:6684 match_filter: Examining AMI event:
Event: ChallengeSent
Privilege: security,all
EventTV: 2024-05-23T09:20:30.305-0400
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 1000
SessionID: 1610757619-6060-5426@BAH.BEF.I.BG
LocalAddress: IPV4/TLS/<<REDACTED>>/5061
RemoteAddress: IPV4/TLS/<<REDACTED>>/59667
Challenge:
derekcrpd commented 4 months ago

Sorry for posting the same image twice. This was supposed to have been the second image, which confirms that the feature code is correct.

5-23-2024 9-36-32 AM

msanthosh18 commented 4 months ago

Hi @derekcrpd , Can you please give a try again by upgrade all modules to latest

derekcrpd commented 4 months ago

Updated all modules. Even rebooted the system. Still receiving the same error.

blazestudios97 commented 4 months ago

We haven't seen any real details or data from all this. Show a verbose call log to show how it is being handled.

derekcrpd commented 4 months ago

[2024-05-28 09:02:54] DEBUG[1751]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003d to use for Request msg INVITE/cseq=241 (rdata0x7f9b8429cb98) [2024-05-28 09:02:54] DEBUG[1751]: chan_pjsip.c:2904 chan_pjsip_session_begin: 1000 [2024-05-28 09:02:54] DEBUG[1751]: chan_pjsip.c:2908 chan_pjsip_session_begin: Direct media no glare mitigation [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:3976 new_invite: 1000 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4065 new_invite: 1000: Call (TLS:<>:39484) to extension '*280' sending 100 Trying [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4591 handle_outgoing_response: 1000: Method is INVITE, Response is 100 Trying [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4610 handle_outgoing_response: 1000 [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<>' into... [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<>' and port ''. [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4707 session_inv_on_state_changed: 1000 Event: TSX_STATE Inv State: INCOMING [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4459 print_debug_details: The state change pertains to the endpoint '1000()' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4464 print_debug_details: The inv session still has an invite_tsx (0x7f9b382de758) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4479 print_debug_details: There is no transaction involved in this state change [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4481 print_debug_details: The current inv state is INCOMING [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4733 session_inv_on_state_changed: 1000: Source of transaction state change is TX_MSG [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4781 session_inv_on_state_changed:
[2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed: 1000 TSX State: Proceeding Inv State: INCOMING [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4459 print_debug_details: The state change pertains to the endpoint '1000()' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4464 print_debug_details: The inv session still has an invite_tsx (0x7f9b382de758) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4470 print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f9b382de758 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4474 print_debug_details: The current transaction state is Proceeding [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4476 print_debug_details: The transaction state change event is TX_MSG [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4481 __print_debug_details: The current inv state is INCOMING [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:5014 session_inv_on_tsx_state_changed: Nothing delayed [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4245 session_on_tsx_state: 1000 TSX State: Proceeding Inv State: INCOMING [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4249 session_on_tsx_state: Topology: Pending: (null topology) Active: (null topology) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4254 session_on_tsx_state:
[2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:769 handle_incoming_sdp: 1000: Media count: 1 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:795 handle_incoming_sdp: 1000: Processing stream 0 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:832 handle_incoming_sdp: 1000: Using audio-0 for new stream name [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:876 handle_incoming_sdp: 1000: Using new stream 0:audio-0:audio:sendrecv (nothing) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:495 ast_sip_session_media_state_add: 1000 Adding position 0 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:541 ast_sip_session_media_state_add: Creating new media session [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:584 ast_sip_session_media_state_add: Setting media session as default for audio [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:589 ast_sip_session_media_state_add: Done [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:929 handle_incoming_sdp: 1000: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_sdp_rtp.c:1501 negotiate_incoming_sdp_stream: 1000 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_sdp_rtp.c:1515 negotiate_incoming_sdp_stream: Incompatible transport [2024-05-28 09:02:54] ERROR[1751]: res_pjsip_session.c:937 handle_incoming_sdp: 1000: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:937 handle_incoming_sdp: 1000: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:960 handle_incoming_sdp: 1000: Handled? no [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4591 handle_outgoing_response: 1000: Method is INVITE, Response is 488 Not Acceptable Here [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4610 handle_outgoing_response: 1000 [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<>' into... [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<>' and port ''. [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4707 session_inv_on_state_changed: 1000 Event: TSX_STATE Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4459 print_debug_details: The state change pertains to the endpoint '1000()' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4464 print_debug_details: The inv session still has an invite_tsx (0x7f9b382de758) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4479 print_debug_details: There is no transaction involved in this state change [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4481 print_debug_details: The current inv state is DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4733 session_inv_on_state_changed: 1000: Source of transaction state change is TX_MSG [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4781 session_inv_on_state_changed:
[2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed: 1000 TSX State: Completed Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4459 print_debug_details: The state change pertains to the endpoint '1000()' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4464 print_debug_details: The inv session still has an invite_tsx (0x7f9b382de758) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4470 print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f9b382de758 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4474 print_debug_details: The current transaction state is Completed [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is TX_MSG [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4481 print_debug_details: The current inv state is DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4847 session_inv_on_tsx_state_changed: Disconnected [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4245 session_on_tsx_state: (null session) TSX State: Completed Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4254 session_on_tsx_state:
[2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4110 new_invite: 1000 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4201 handle_new_invite_request: Request: Session: 1000 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4319 session_on_rx_request: (null session) Handled request INVITE ? yes [2024-05-28 09:02:54] DEBUG[1751]: chan_pjsip.c:2925 chan_pjsip_session_end: 1000 [2024-05-28 09:02:54] DEBUG[1751]: chan_pjsip.c:2928 chan_pjsip_session_end: No channel [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:2912 session_destructor: 1000: Destroying SIP session [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f9b382e6c58 for Request msg ACK/cseq=241 (rdata0x7f9b84148f18) [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003d to use for Request msg ACK/cseq=241 (rdata0x7f9b84148f18) [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '<>' into... [2024-05-28 09:02:54] DEBUG[1751]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '<>' and port ''. [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_endpoint_identifier_ip.c:258 ip_identify_match_check: Source address <>:39484 does not match identify '<>' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '1000' domain '<>' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '1000' domain '<>' [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed: (null session) TSX State: Confirmed Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4457 print_debug_details: inv_session 0x7f9b38303448 has no ast session [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4464 print_debug_details: The inv session still has an invite_tsx (0x7f9b382de758) [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4470 print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f9b382de758 [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4474 print_debug_details: The current transaction state is Confirmed [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4476 __print_debug_details: The transaction state change event is RX_MSG [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4481 print_debug_details: The current inv state is DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4837 session_inv_on_tsx_state_changed: Session ended [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4245 session_on_tsx_state: (null session) TSX State: Confirmed Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1751]: res_pjsip_session.c:4254 session_on_tsx_state:
[2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4825 session_inv_on_tsx_state_changed: (null session) TSX State: Terminated Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4445 print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4457 print_debug_details: inv_session 0x7f9b38303448 has no ast session [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4467 __print_debug_details: The inv session does NOT have an invite_tsx [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4470 print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f9b382de758 [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4474 print_debug_details: The current transaction state is Terminated [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4476 print_debug_details: The transaction state change event is TIMER [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4481 print_debug_details: The current inv state is DISCONNCTD [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4837 session_inv_on_tsx_state_changed: Session ended [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4245 session_on_tsx_state: (null session) TSX State: Terminated Inv State: DISCONNCTD [2024-05-28 09:02:54] DEBUG[1750]: res_pjsip_session.c:4254 session_on_tsx_state:
[2024-05-28 09:02:58] DEBUG[1762]: res_pjsip_registrar.c:1377 check_expiration_thread: Woke up at 1716901378 Interval: 30 [2024-05-28 09:02:58] DEBUG[1762]: res_pjsip_registrar.c:1384 check_expiration_thread: Expiring 0 contacts

blazestudios97 commented 4 months ago

No, that is a debug not a call log. You don't need debug output for this. So do asterisk -rvvvvvvvvv and don't turn on debug.

derekcrpd commented 4 months ago

With just that I receive the following when I attempt to activate it: ERROR[72748]: res_pjsip_session.c:937 handle_incoming_sdp: 1000: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing)

blazestudios97 commented 4 months ago

This is a codec issue. What codecs are being used on the device and what codecs does the PJSIP endpoint have allowed?

derekcrpd commented 4 months ago

Just the basic ones that are enabled by default... ulaw, alaw, gsm, g726, and g722. The endpoint supports g711u, g729a, g722 and gsm. But is a FreePBX feature code being sent all the way through the trunk? As far as the system recording that are attached to the call flow... I tried changing them back to and from default to see if that made any difference, though it did not.

derekcrpd commented 4 months ago

Also forgot to mention. The phone itself supports g722 and g726

derekcrpd commented 4 months ago

Ok, feel a bit stupid on this one. The issue had to do with SRTP encryption. It was not enabled on the line that was attempting to set the call flow control. Once it was set to "enabled and forced" on the phone then everything works fine. msanthosh18, thank you for putting up with me on this one. :)