ziki
January 22, 2021, 1:50pm
1
Hi,
We have a problem where pjsip endpoints become unavailable. In fact, we have a Kamailio in front of our Asterisk and client are registered with Kamailio. Asterisk is configured with realtime to fetch endpoints and aors from the Kamailio DB.
I have seen other posts of people having the same problem, the solution was to set qualify_frequency > 0 but we don’t want to qualify since Kamailio is handling this part of the job.
Does anyone have any idea how to solve this problem?
Our major problem with this is when we are using queues, Asterisk is not trying to ring these extensions which are in Unavailable state.
Please find some more information below.
asterisk1*CLI> core show version
Asterisk 18.1.0 built by root @ asterisk1 on a x86_64 running Linux on 2020-12-02 23:06:28 UTC
asterisk1*CLI> pjsip show endpoint 8033@demo.mydomain.com
Endpoint: <Endpoint/CID.....................................> <State.....> <Channels.>
I/OAuth: <AuthId/UserName...........................................................>
Aor: <Aor............................................> <MaxContact>
Contact: <Aor/ContactUri..........................> <Hash....> <Status> <RTT(ms)..>
Transport: <TransportId........> <Type> <cos> <tos> <BindAddress..................>
Identify: <Identify/Endpoint.........................................................>
Match: <criteria.........................>
Channel: <ChannelId......................................> <State.....> <Time.....>
Exten: <DialedExten...........> CLCID: <ConnectedLineCID.......>
==========================================================================================
Endpoint: 8033@demo.mydomain.com Unavailable 0 of inf
Aor: 8033-demo.mydomain.com 1
Contact: 8033-demo.mydomain.com/sip:8033@demo.mydomain. 83f77ff95b NonQual nan
Transport: transport-udp udp 0 0 0.0.0.0:5080
ParameterName : ParameterValue
===================================================================================================
100rel : yes
accept_multiple_sdp_answers : false
accountcode :
acl :
aggregate_mwi : true
allow : (alaw)
allow_overlap : true
allow_subscribe : true
allow_transfer : true
aors : 8033-demo.mydomain.com
asymmetric_rtp_codec : false
auth :
bind_rtp_to_media_address : false
bundle : false
call_group :
callerid : <unknown>
callerid_privacy : allowed_not_screened
callerid_tag :
codec_prefs_incoming_answer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_incoming_offer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_outgoing_answer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_outgoing_offer : prefer:pending, operation:union, keep:all, transcode:allow
connected_line_method : invite
contact_acl :
context : default
cos_audio : 0
cos_video : 0
device_state_busy_at : 0
direct_media : false
direct_media_glare_mitigation : none
direct_media_method : invite
disable_direct_media_on_nat : false
dtls_auto_generate_cert : No
dtls_ca_file :
dtls_ca_path :
dtls_cert_file :
dtls_cipher :
dtls_fingerprint : SHA-256
dtls_private_key :
dtls_rekey : 0
dtls_setup : active
dtls_verify : No
dtmf_mode : auto
fax_detect : false
fax_detect_timeout : 0
follow_early_media_fork : true
force_avp : false
force_rport : true
from_domain : demo.mydomain.com
from_user :
g726_non_standard : false
ice_support : false
identify_by : username,ip
ignore_183_without_sdp : false
inband_progress : false
incoming_call_offer_pref : local
incoming_mwi_mailbox :
language :
mailboxes :
max_audio_streams : 1
max_video_streams : 1
media_address :
media_encryption : no
media_encryption_optimistic : false
media_use_received_transport : false
message_context :
moh_passthrough : false
moh_suggest : default
mwi_from_user :
mwi_subscribe_replaces_unsolicited : no
named_call_group :
named_pickup_group :
notify_early_inuse_ringing : false
one_touch_recording : false
outbound_auth :
outbound_proxy : sip:192.168.102.10
outgoing_call_offer_pref : remote_merge
pickup_group :
preferred_codec_only : false
record_off_feature : automixmon
record_on_feature : automixmon
refer_blind_progress : true
rewrite_contact : false
rpid_immediate : false
rtcp_mux : false
rtp_engine : asterisk
rtp_ipv6 : false
rtp_keepalive : 0
rtp_symmetric : false
rtp_timeout : 0
rtp_timeout_hold : 0
sdp_owner : -
sdp_session : Asterisk
send_connected_line : yes
send_diversion : true
send_history_info : false
send_pai : true
send_rpid : true
set_var :
srtp_tag_32 : false
stir_shaken : false
sub_min_expiry : 0
subscribe_context :
suppress_q850_reason_headers : false
t38_udptl : false
t38_udptl_ec : none
t38_udptl_ipv6 : false
t38_udptl_maxdatagram : 0
t38_udptl_nat : false
timers : yes
timers_min_se : 90
timers_sess_expires : 1800
tone_zone :
tos_audio : 0
tos_video : 0
transport : transport-udp
trust_connected_line : yes
trust_id_inbound : false
trust_id_outbound : false
use_avpf : false
use_ptime : false
user_eq_phone : false
voicemail_extension :
webrtc : no
Thank you,
Cyrille
Unavailable is detected if qualify is enabled but no timely response is received when OPTIONS is sent. I think it is also detected when a registration is timed out without being refreshed first.
One reason for registrations to fail is a firewall or NAT rule timing out, and one way of avoiding that is to use qualify to generate periodic signalling traffic.
1 Like
ziki
January 22, 2021, 3:29pm
3
Qualify is disabled in my case and registrations are not handled by Asterisk.
The strange thing is that when I make a “pjsip reload”, all the unavailable endpoints become “Not in use” but after a certain amount of time it becomes “Unavailable” again.
asterisk1*CLI> pjsip show aor 8033-demo.mydomain.com
Aor: <Aor..............................................> <MaxContact>
Contact: <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================
Aor: 8033-demo.mydomain.com 1
Contact: 8033-demo.mydomain.com/sip:8033@demo.mydomain.co 83f77ff95b NonQual nan
ParameterName : ParameterValue
===============================================
authenticate_qualify : false
contact : sip:8033@demo.mydomain.com
default_expiration : 3600
mailboxes :
max_contacts : 1
maximum_expiration : 7200
minimum_expiration : 60
outbound_proxy : sip:192.168.102.10
qualify_frequency : 0
qualify_timeout : 3.000000
remove_existing : false
support_path : false
voicemail_extension :
Please provide the actual content of the aor section in your configuration (not the interpreted contents of memory).
ziki
January 22, 2021, 4:48pm
5
I’m using realtime from a Mysql DB.
ziki
January 23, 2021, 9:33am
6
My SQL record for aor contains the following data:
id: 8033-demo.mydomain.com sip:8033@demo.mydomain.com
Are they by any chance becoming unavailable after exactly one hour?
ziki
January 23, 2021, 12:16pm
8
One hour after last call? I don’t think, I have now a lot of endpoints connected which are in the state “Not in use” and they have not made any calls today.
That seems to invalidate my theory, although my intended meaning was one hour after the a configuration reload, not a call.
I think you are going to have to turn up the logging until you see the event triggering the change of state, and/or look through the source code to find the possible triggers for the change of state. I’m not aware or ICMP unreachable, to normal traffic, doing this, but it is conceivable that it does.
ziki
January 23, 2021, 8:29pm
10
I have already tried to look in the source code but the implementation of pjsip is much complex than the legacy chan_sip. I’ll check again and also I hope that someone could help me here.
ziki
January 25, 2021, 11:03am
11
I have enabled debugging and here’s an example where an endpoint seems to become unavailable.
Is someone knows enough the pjsip stack to tell me why it’s happening?
[Jan 25 11:49:50] VERBOSE[31236] res_pjsip_logger.c: <--- Received SIP request (463 bytes) from UDP:192.168.102.10:5060 --->
BYE sip:192.168.102.20:5080 SIP/2.0
Via: SIP/2.0/UDP 192.168.102.10;branch=z9hG4bKb7da.fb5b4bd973f1650ecd7d52d14b8b3caf.0
Via: SIP/2.0/WSS 192.0.2.175;rport=52757;received=195.16.9.75;branch=z9hG4bK280761
Max-Forwards: 69
To: <sip:192.168.102.20:5080>;tag=805018f1-ab89-4578-aaa3-2fac5d73cb61
From: <sip:8624@demo.mydomain.com>;tag=if427hlr6e
Call-ID: ip53s10k8jb19cc4taj8
CSeq: 4723 BYE
Supported: outbound
User-Agent: SIP.js/0.13.8
Content-Length: 0
[Jan 25 11:49:50] DEBUG[31236] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fd9fc051a28 for Request msg BYE/cseq=4723 (rdata0x7fd9ec3d9278)
[Jan 25 11:49:50] DEBUG[31236] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-000000af associated with dialog dlg0x7fd9fc051a28
[Jan 25 11:49:50] DEBUG[2914] netsock2.c: Splitting '192.168.102.10' into...
[Jan 25 11:49:50] DEBUG[2914] netsock2.c: ...host '192.168.102.10' and port ''.
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[Jan 25 11:49:50] VERBOSE[2914] res_pjsip_logger.c: <--- Transmitting SIP response (436 bytes) to UDP:192.168.102.10:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.102.10;rport=5060;received=192.168.102.10;branch=z9hG4bKb7da.fb5b4bd973f1650ecd7d52d14b8b3caf.0
Via: SIP/2.0/WSS 192.0.2.175;rport=52757;received=195.16.9.75;branch=z9hG4bK280761
Call-ID: ip53s10k8jb19cc4taj8
From: <sip:8624@demo.mydomain.com>;tag=if427hlr6e
To: <sip:192.168.102.20>;tag=805018f1-ab89-4578-aaa3-2fac5d73cb61
CSeq: 4723 BYE
Server: Asterisk PBX 18.1.0
Content-Length: 0
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a TSX State: Completed Inv State: CONFIRMED
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The state change pertains to the endpoint '8624@demo.mydomain.com(PJSIP/8624@demo.mydomain.com-0002506a)'
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fd9ec0ff948
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The current transaction state is Completed
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Nothing delayed
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a TSX State: Completed Inv State: CONFIRMED
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a Event: TSX_STATE Inv State: DISCONNCTD
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The state change pertains to the endpoint '8624@demo.mydomain.com(PJSIP/8624@demo.mydomain.com-0002506a)'
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: There is no transaction involved in this state change
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a: Source of transaction state change is RX_MSG
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a: Received request
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a: Method is BYE
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a TSX State: Completed Inv State: DISCONNCTD
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The state change pertains to the endpoint '8624@demo.mydomain.com(PJSIP/8624@demo.mydomain.com-0002506a)'
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fd9ec0ff948
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The current transaction state is Completed
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The transaction state change event is RX_MSG
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: The current inv state is DISCONNCTD
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Nothing delayed
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a TSX State: Completed Inv State: DISCONNCTD
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>
[Jan 25 11:49:50] DEBUG[2914] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[2914] chan_pjsip.c: PJSIP/8624@demo.mydomain.com-0002506a
[Jan 25 11:49:50] DEBUG[2914] chan_pjsip.c: [Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge_channel.c: Setting 0x7fd9f435ea60(PJSIP/8624@demo.mydomain.com-0002506a) state from:0 to:1
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge_channel.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: pulling 0x7fd9f435ea60(PJSIP/8624@demo.mydomain.com-0002506a)
[Jan 25 11:49:50] VERBOSE[4771][C-00010826] bridge_channel.c: Channel PJSIP/8624@demo.mydomain.com-0002506a left 'simple_bridge' basic-bridge <4311869c-3449-45d1-95c5-3dc6f62c3583>
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge_channel.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: 0x7fd9f435ea60(PJSIP/8624@demo.mydomain.com-0002506a) is leaving simple_bridge technology
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: dissolving bridge with cause 16(Normal Clearing)
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge_channel.c: Setting 0x7fd9f46c1300(PJSIP/sipwise-0002506b) state from:0 to:2
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: queueing action type:13 sub:1001
[Jan 25 11:49:50] DEBUG[4771][C-00010826] stasis_bridges.c: Update: 0x7fd9f4060428 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: 4311869c-3449-45d1-95c5-3dc6f62c3583
[Jan 25 11:49:50] DEBUG[4771][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583 is dissolved, not performing smart bridge operation.
[Jan 25 11:49:50] DEBUG[4771][C-00010826] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 25 11:49:50] DEBUG[4771][C-00010826] app_dial.c: PJSIP/8624@demo.mydomain.com-0002506a: Done
[Jan 25 11:49:50] DEBUG[4771][C-00010826] app_macro.c: Spawn extension (macro-dialOut,s,7) exited non-zero on 'PJSIP/8624@demo.mydomain.com-0002506a' in macro 'dialOut'
[Jan 25 11:49:50] VERBOSE[4771][C-00010826] app_macro.c: Spawn extension (macro-dialOut, s, 7) exited non-zero on 'PJSIP/8624@demo.mydomain.com-0002506a' in macro 'dialOut'
[Jan 25 11:49:50] DEBUG[4771][C-00010826] pbx.c: Spawn extension (demo-intern,+33613232065,1) exited non-zero on 'PJSIP/8624@demo.mydomain.com-0002506a'
[Jan 25 11:49:50] VERBOSE[4771][C-00010826] pbx.c: Spawn extension (demo-intern, +33613232065, 1) exited non-zero on 'PJSIP/8624@demo.mydomain.com-0002506a'
[Jan 25 11:49:50] DEBUG[4771][C-00010826] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/8624@demo.mydomain.com-0002506a'
[Jan 25 11:49:50] DEBUG[4771][C-00010826] channel.c: Channel 0x7fda08222bc0 'PJSIP/8624@demo.mydomain.com-0002506a' hanging up. Refs: 2
[Jan 25 11:49:50] DEBUG[4771][C-00010826] chan_pjsip.c: PJSIP/8624@demo.mydomain.com-0002506a
[Jan 25 11:49:50] DEBUG[4771][C-00010826] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jan 25 11:49:50] DEBUG[4771][C-00010826] chan_pjsip.c: Cause: 0
[Jan 25 11:49:50] DEBUG[31228] cdr.c: Finalized CDR for PJSIP/8624@demo.mydomain.com-0002506a - start 1611571725.283528 answer 1611571740.007446 end 1611571790.980324 dur 65.696 bill 50.972 dispo ANSWERED
[Jan 25 11:49:50] DEBUG[4782][C-00010826] bridge_channel.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: pulling 0x7fd9f46c1300(PJSIP/sipwise-0002506b)
[Jan 25 11:49:50] VERBOSE[4782][C-00010826] bridge_channel.c: Channel PJSIP/sipwise-0002506b left 'simple_bridge' basic-bridge <4311869c-3449-45d1-95c5-3dc6f62c3583>
[Jan 25 11:49:50] DEBUG[4782][C-00010826] bridge_channel.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: 0x7fd9f46c1300(PJSIP/sipwise-0002506b) is leaving simple_bridge technology
[Jan 25 11:49:50] DEBUG[4782][C-00010826] stasis_bridges.c: Update: 0x7fd9fc631048 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: 4311869c-3449-45d1-95c5-3dc6f62c3583
[Jan 25 11:49:50] DEBUG[4782][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583 is dissolved, not performing smart bridge operation.
[Jan 25 11:49:50] DEBUG[4782][C-00010826] chan_pjsip.c: PJSIP/sipwise-0002506b: Indicated Media SSRC change
[Jan 25 11:49:50] DEBUG[4782][C-00010826] chan_pjsip.c: PJSIP/sipwise-0002506b
[Jan 25 11:49:50] DEBUG[4782][C-00010826] channel.c: Channel 0x7fd9f42004b0 'PJSIP/sipwise-0002506b' hanging up. Refs: 2
[Jan 25 11:49:50] DEBUG[4782][C-00010826] chan_pjsip.c: PJSIP/sipwise-0002506b
[Jan 25 11:49:50] DEBUG[4782][C-00010826] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[Jan 25 11:49:50] DEBUG[4782][C-00010826] chan_pjsip.c: Cause: 0
[Jan 25 11:49:50] DEBUG[31214][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: actually destroying basic bridge, nobody wants it anymore
[Jan 25 11:49:50] DEBUG[31214][C-00010826] stasis_bridges.c: Update: 0x7fd9f40d4278 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: <none>
[Jan 25 11:49:50] DEBUG[31214][C-00010826] stasis.c: Destroying topic. name: bridge:all/bridge:4311869c-3449-45d1-95c5-3dc6f62c3583, detail:
[Jan 25 11:49:50] DEBUG[31214][C-00010826] stasis.c: Topic 'bridge:all/bridge:4311869c-3449-45d1-95c5-3dc6f62c3583': 0x7fd9f430dfd0 destroyed
[Jan 25 11:49:50] DEBUG[31214][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: calling basic bridge destructor
[Jan 25 11:49:50] DEBUG[31214][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: calling simple_bridge technology stop
[Jan 25 11:49:50] DEBUG[31214][C-00010826] bridge.c: Bridge 4311869c-3449-45d1-95c5-3dc6f62c3583: calling simple_bridge technology destructor
[Jan 25 11:49:50] DEBUG[4289] chan_pjsip.c: PJSIP/8624@demo.mydomain.com-0002506a
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/8624@demo.mydomain.com-0002506a Response 0
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) DTLS stop
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda0847bf50) ICE RTP transport deallocating
[Jan 25 11:49:50] DEBUG[4289] rtp_engine.c: Destroyed RTP instance '0x7fda0847bf50'
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[4289] channel.c: Channel 0x7fda08222bc0 'PJSIP/8624@demo.mydomain.com-0002506a' destroying
[Jan 25 11:49:50] DEBUG[4289] stasis.c: Destroying topic. name: channel:1611571725.201399, detail:
[Jan 25 11:49:50] DEBUG[4289] stasis.c: Topic 'channel:1611571725.201399': 0x7fda080bf430 destroyed
[Jan 25 11:49:50] DEBUG[4289] channel_internal_api.c: <initializing>: MultistreamFormats: (nothing)
[Jan 25 11:49:50] DEBUG[4289] channel_internal_api.c: Channel is being initialized or destroyed
[Jan 25 11:49:50] DEBUG[4289] chan_pjsip.c: [Jan 25 11:49:50] DEBUG[4289] chan_pjsip.c: PJSIP/sipwise-0002506b
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/sipwise-0002506b Response 0
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) DTLS stop
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) DTLS srtp - stopped timeout timer'
[Jan 25 11:49:50] DEBUG[4289] res_rtp_asterisk.c: (0x7fda08082940) ICE RTP transport deallocating
[Jan 25 11:49:50] DEBUG[4289] rtp_engine.c: Destroyed RTP instance '0x7fda08082940'
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/sipwise-0002506b: Method is BYE
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/sipwise-0002506b
[Jan 25 11:49:50] DEBUG[4289] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.102.10'
[Jan 25 11:49:50] DEBUG[4289] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.102.10' is 'UDP transport'
[Jan 25 11:49:50] DEBUG[4289] res_pjsip/pjsip_resolver.c: Target '192.168.102.10' is an IP address, skipping resolution
[Jan 25 11:49:50] DEBUG[4289] netsock2.c: Splitting '192.168.102.10' into...
[Jan 25 11:49:50] DEBUG[4289] netsock2.c: ...host '192.168.102.10' and port ''.
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[Jan 25 11:49:50] VERBOSE[4289] res_pjsip_logger.c: <--- Transmitting SIP request (1247 bytes) to UDP:192.168.102.10:5060 --->
BYE sip:ngcp-lb@1.2.3.4:5060;ngcpct=7369703a3132372e302e302e313a353038303b707278726f7574653d31 SIP/2.0
Via: SIP/2.0/UDP 192.168.102.20:5080;rport;branch=z9hG4bKPj1d06f6b1-95c8-4f89-a39d-775718060c09
From: <sip:3226168624@sip.mydomain.com>;tag=bd61b01b-ca16-4425-85c1-5b136839a4e6
To: <sip:+33613232065@sip.mydomain.com>;tag=1CC0FFF5-600EA20D00064DA4-6950E700
Call-ID: 607da016-9df4-458d-81bb-6fca5e6e3cda
CSeq: 13903 BYE
Route: <sip:192.168.102.10;lr;r2=on;ftag=bd61b01b-ca16-4425-85c1-5b136839a4e6;did=902.1f1;nat=yes>
Route: <sip:1.2.3.5;lr;r2=on;ftag=bd61b01b-ca16-4425-85c1-5b136839a4e6;did=902.1f1;nat=yes>
Route: <sip:1.2.3.4;lr;r2=on;ftag=bd61b01b-ca16-4425-85c1-5b136839a4e6;nat=yes;ngcplb=yes;socket=udp:1.2.3.4:5060>
Route: <sip:127.0.0.1;lr;r2=on;ftag=bd61b01b-ca16-4425-85c1-5b136839a4e6;nat=yes;ngcplb=yes;socket=udp:1.2.3.4:5060>
Route: <sip:127.0.0.1:5062;lr;ftag=bd61b01b-ca16-4425-85c1-5b136839a4e6;did=902.42c;ice_caller=strip;ice_callee=strip;caller_tp=transparent;callee_tp=transparent;caller_iface=ext;callee_iface=int_destiny;aset=50;rtpprx=yes;vsf=eTdydU5XcVNiOVZ3awJUW2sLP2BoK
GtiGxp5Vgg->
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: Asterisk PBX 18.1.0
Content-Length: 0
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/sipwise-0002506b TSX State: Calling Inv State: CONFIRMED
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The state change pertains to the endpoint 'sipwise(PJSIP/sipwise-0002506b)'
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fda00916758
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The current transaction state is Calling
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The transaction state change event is TX_MSG
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: The current inv state is CONFIRMED
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: Nothing delayed
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: PJSIP/sipwise-0002506b TSX State: Calling Inv State: CONFIRMED
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: Topology: Pending: (null topology) Active: (null topology)
[Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[4289] res_pjsip_session.c: [Jan 25 11:49:50] DEBUG[4289] channel.c: Channel 0x7fd9f42004b0 'PJSIP/sipwise-0002506b' destroying
[Jan 25 11:49:50] DEBUG[31220] devicestate.c: No provider found, checking channel drivers for PJSIP - 8624@demo.mydomain.com
[Jan 25 11:49:50] DEBUG[31230] stasis_bridges.c: Update: 0x7fd9f4060428 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: 4311869c-3449-45d1-95c5-3dc6f62c3583
[Jan 25 11:49:50] DEBUG[31230] stasis_bridges.c: Update: 0x7fd9fc631048 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: 4311869c-3449-45d1-95c5-3dc6f62c3583
[Jan 25 11:49:50] DEBUG[31230] stasis_bridges.c: Update: 0x7fd9f40d4278 Old: 4311869c-3449-45d1-95c5-3dc6f62c3583 New: <none>
[Jan 25 11:49:50] DEBUG[31228] cdr.c: CDR for PJSIP/sipwise-0002506b is dialed and has no Party B; discarding
[Jan 25 11:49:50] DEBUG[31220] res_odbc.c: Reusing ODBC handle 0x7fd9f46fa2a0 from class 'kamailio'
[Jan 25 11:49:50] DEBUG[31220] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[Jan 25 11:49:50] DEBUG[31220] res_config_odbc.c: Parameter 1 ('id') = '8624@demo.mydomain.com'
[Jan 25 11:49:50] DEBUG[31220] res_odbc.c: Releasing ODBC handle 0x7fd9f46fa2a0 into pool
[Jan 25 11:49:50] DEBUG[31220] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Jan 25 11:49:50] DEBUG[31220] devicestate.c: Changing state for PJSIP/8624@demo.mydomain.com - state 5 (Unavailable)
[Jan 25 11:49:50] DEBUG[31267] app_queue.c: Device 'PJSIP/8624@demo.mydomain.com' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
Thank you,
Cyrille
jcolp
January 25, 2021, 11:09am
12
Does the issue happen when realtime is not involved? If so, then it’s likely due to realtime and you’d need to file an issue[1] with steps for reproducing it.
[1] https://issues.asterisk.org/jira
ziki
January 25, 2021, 11:29am
13
All our solution is based on realtime, so I don’t have endpoints that are not realtime.
Describing the steps to reproduce the problem is going to be difficult because we are using kamailio in front of Asterisk and ps_endpoints for realtime is a mysql view from the Kamailio database.
Currently, my view returns only the following fields:
id
Do you maybe have an idea about a field that should be present and its not and can cause this issue?
Cyrille
jcolp
January 25, 2021, 11:30am
14
There aren’t fields that would have an impact like that. If it would be difficult, then you’d need to find a simpler example.
ziki
February 1, 2021, 8:45pm
15
I can confirm that this problem is related to realtime. I have configured all my endpoints/aor using static files and we had zero problem today.
My config was:
asterisk.conf
[settings]
ps_aors => odbc,kamailio
ps_endpoints => odbc,kamailio
sorcery.conf
[res_pjsip]
endpoint=realtime,ps_endpoints
endpoint=config,pjsip.conf,criteria=type=endpoint
aor=realtime,ps_aors
aor=config,pjsip.conf,criteria=type=aor
Maybe something is wrong with my realtime config?
Cyrille
Same issue here. When I added the endpoint to the real-time database it came “Unavailable”. After “pjsip reload” it become to the “Not in use” state.
Our asterisk is not the registrar and also we don’t wanna use qualify to solve this problem because Kamailio handle it.
Asterisk 18.2.0
1 Like
system
April 2, 2021, 4:20pm
17
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.