TECH7Fox / asterisk-hass-addons

Asterisk add-on for Home Assistant
https://tech7fox.github.io/sip-hass-docs/
MIT License
73 stars 25 forks source link

Can't dial to card #144

Closed TECH7Fox closed 2 years ago

TECH7Fox commented 2 years ago

Multiple people are having trouble with PJSIP when calling to the card. Calling from does work.

Here is a entire log with debug enabled:

[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xaaab09aaa4c8) ICE add candidate: [fe80::f402:9eff:fe54:1049]:10324, 2130706431
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xaaab09aaa4c8) ICE add candidate: [fe80::24ec:7cff:fed1:f62]:10324, 2130706431
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xaaab09aaa4c8) ICE add candidate: [fe80::1cca:39ff:fe14:ee7a]:10324, 2130706431
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:3663 rtp_add_candidates_to_ice: (0xaaab09aaa4c8) ICE request STUN TCP RTP candidate
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xffff100450b8) ICE add candidate: 149.113.25.91:13432, 1694498815
[Mar 29 01:48:24] DEBUG[690]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0xffff100450b8' is setup and ready to go
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:1760 ast_rtp_ice_change_components: (0xffff100450b8) ICE change number of components 2 -> 1
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:979 ice_reset_session: (0xffff100450b8) ICE resetting
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:981 ice_reset_session:  (0xffff100450b8) ICE nevermind, not ready for a reset
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:8440 ast_rtp_prop_set: (0xffff100450b8) RTCP setup on RTP instance
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:2151 ast_rtp_dtls_set_configuration: (0xffff100450b8) DTLS RTP setup
[Mar 29 01:48:24] DEBUG[690]: res_rtp_asterisk.c:1857 dtls_setup_rtcp: (0xffff100450b8) DTLS RTCP setup
[Mar 29 01:48:24] DEBUG[690]: res_srtp.c:676 crypto_init_keys: local_key64 mPYoz1kPANc8UdLt17yO35Up40DJmGo4GigvmbWc len 40
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_sdp_rtp.c:1312 add_msid_to_stream: Stream msid: 0xffff100c1b90 audio f559c09a-13cb-44ce-8dbe-b6a4a7f3f1d5 c550350a-9cd4-42a6-856b-14ac64a58ebb
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_sdp_rtp.c:2034 create_outgoing_sdp_stream:  RC: 1
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:5006 add_sdp_streams:  Handled
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:5194 create_local_sdp:  PJSIP/100-00000005: Adding bundle groups (if available)
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:5200 create_local_sdp:  PJSIP/100-00000005: Copying connection details
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:5244 create_local_sdp:  PJSIP/100-00000005
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:2876 ast_sip_session_create_invite:  
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4496 handle_outgoing_request:  PJSIP/100-00000005: Method is INVITE
[Mar 29 01:48:24]     -- PJSIP/100-00000005 connected line has changed. Saving it until answer for PJSIP/8001-00000004
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4506 handle_outgoing_request:  PJSIP/100-00000005
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xffff10043448) ICE add candidate: 149.113.25.91:12904, 1694498815
[Mar 29 01:48:24] DEBUG[690]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '149.113.25.91'
[Mar 29 01:48:24] DEBUG[790]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0xffff10043448' is setup and ready to go
[Mar 29 01:48:24] DEBUG[690]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '149.113.25.91' is '(null)'
[Mar 29 01:48:24] DEBUG[690]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '149.113.25.91' is an IP address, skipping resolution
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:1760 ast_rtp_ice_change_components: (0xffff10043448) ICE change number of components 2 -> 1
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:979 ice_reset_session: (0xffff10043448) ICE resetting
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:981 ice_reset_session:  (0xffff10043448) ICE nevermind, not ready for a reset
[Mar 29 01:48:24] DEBUG[690]: res_http_websocket.c:381 __ast_websocket_write: Writing websocket text frame, length 3384
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4630 session_inv_on_state_changed:  PJSIP/100-00000005 Event: TSX_STATE  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4656 session_inv_on_state_changed: PJSIP/100-00000005: Source of transaction state change is TX_MSG
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4704 session_inv_on_state_changed:  
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/100-00000005 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4936 session_inv_on_tsx_state_changed:  Nothing delayed
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4180 session_on_tsx_state:  PJSIP/100-00000005 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4184 session_on_tsx_state:  Topology: Pending:  <0:audio-0:audio:sendrecv (ulaw|alaw)>  Active: (null topology)
[Mar 29 01:48:24] DEBUG[690]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 29 01:48:24] DEBUG[690]: chan_pjsip.c:2382 call:  RC: 0
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1329 ast_rtp_ice_add_cand: (0xaaab09aaa4c8) ICE add candidate: 149.113.25.91:10324, 1694498815
[Mar 29 01:48:24] DEBUG[789]: rtp_engine.c:543 ast_rtp_instance_new: RTP instance '0xaaab09aaa4c8' is setup and ready to go
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1760 ast_rtp_ice_change_components: (0xaaab09aaa4c8) ICE change number of components 2 -> 1
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:979 ice_reset_session: (0xaaab09aaa4c8) ICE resetting
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:981 ice_reset_session:  (0xaaab09aaa4c8) ICE nevermind, not ready for a reset
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:8440 ast_rtp_prop_set: (0xffff10043448) RTCP setup on RTP instance
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:2151 ast_rtp_dtls_set_configuration: (0xffff10043448) DTLS RTP setup
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:8440 ast_rtp_prop_set: (0xaaab09aaa4c8) RTCP setup on RTP instance
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:2151 ast_rtp_dtls_set_configuration: (0xaaab09aaa4c8) DTLS RTP setup
[Mar 29 01:48:24] DEBUG[790]: res_rtp_asterisk.c:1857 dtls_setup_rtcp: (0xffff10043448) DTLS RTCP setup
[Mar 29 01:48:24] DEBUG[790]: res_srtp.c:676 crypto_init_keys: local_key64 fkl8290o3An/Gm8FqwbfGHZgDYGX0yxRVQQ0MqmD len 40
[Mar 29 01:48:24] DEBUG[789]: res_rtp_asterisk.c:1857 dtls_setup_rtcp: (0xaaab09aaa4c8) DTLS RTCP setup
[Mar 29 01:48:24] DEBUG[789]: res_srtp.c:676 crypto_init_keys: local_key64 BTRJD1KxK1Umg6vMTRhgka72mT/IVKbRTzZQBtmn len 40
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_sdp_rtp.c:1312 add_msid_to_stream: Stream msid: 0xffff100e6090 audio e3b29eb8-5459-481e-bf95-0b5fe684e778 e7830ac1-e00e-47b4-8e76-027e928345b2
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_sdp_rtp.c:2034 create_outgoing_sdp_stream:  RC: 1
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:5006 add_sdp_streams:  Handled
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:5194 create_local_sdp:  PJSIP/100-00000007: Adding bundle groups (if available)
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:5200 create_local_sdp:  PJSIP/100-00000007: Copying connection details
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:5244 create_local_sdp:  PJSIP/100-00000007
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:2876 ast_sip_session_create_invite:  
[Mar 29 01:48:24]     -- PJSIP/100-00000007 connected line has changed. Saving it until answer for PJSIP/8001-00000004
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4496 handle_outgoing_request:  PJSIP/100-00000007: Method is INVITE
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4506 handle_outgoing_request:  PJSIP/100-00000007
[Mar 29 01:48:24] DEBUG[790]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '149.113.25.91'
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_sdp_rtp.c:1312 add_msid_to_stream: Stream msid: 0xffff1004d720 audio 24428e41-f0d8-47f2-a212-386648c52037 34aa98d8-f67d-4c67-bcde-3063cf5ee985
[Mar 29 01:48:24] DEBUG[790]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '149.113.25.91' is '(null)'
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_sdp_rtp.c:2034 create_outgoing_sdp_stream:  RC: 1
[Mar 29 01:48:24] DEBUG[790]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '149.113.25.91' is an IP address, skipping resolution
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:5006 add_sdp_streams:  Handled
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:5194 create_local_sdp:  PJSIP/100-00000006: Adding bundle groups (if available)
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:5200 create_local_sdp:  PJSIP/100-00000006: Copying connection details
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:5244 create_local_sdp:  PJSIP/100-00000006
[Mar 29 01:48:24] DEBUG[790]: res_http_websocket.c:381 __ast_websocket_write: Writing websocket text frame, length 3384
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:2876 ast_sip_session_create_invite:  
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4496 handle_outgoing_request:  PJSIP/100-00000006: Method is INVITE
[Mar 29 01:48:24]     -- PJSIP/100-00000006 connected line has changed. Saving it until answer for PJSIP/8001-00000004
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4630 session_inv_on_state_changed:  PJSIP/100-00000007 Event: TSX_STATE  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4656 session_inv_on_state_changed: PJSIP/100-00000007: Source of transaction state change is TX_MSG
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4704 session_inv_on_state_changed:  
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4506 handle_outgoing_request:  PJSIP/100-00000006
[Mar 29 01:48:24] DEBUG[789]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '149.113.25.91'
[Mar 29 01:48:24] DEBUG[789]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '149.113.25.91' is '(null)'
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/100-00000007 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[789]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '149.113.25.91' is an IP address, skipping resolution
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4936 session_inv_on_tsx_state_changed:  Nothing delayed
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4180 session_on_tsx_state:  PJSIP/100-00000007 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4184 session_on_tsx_state:  Topology: Pending:  <0:audio-0:audio:sendrecv (ulaw|alaw)>  Active: (null topology)
[Mar 29 01:48:24] DEBUG[790]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 29 01:48:24] DEBUG[790]: chan_pjsip.c:2382 call:  RC: 0
[Mar 29 01:48:24] DEBUG[789]: res_http_websocket.c:381 __ast_websocket_write: Writing websocket text frame, length 3385
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4630 session_inv_on_state_changed:  PJSIP/100-00000006 Event: TSX_STATE  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4656 session_inv_on_state_changed: PJSIP/100-00000006: Source of transaction state change is TX_MSG
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4704 session_inv_on_state_changed:  
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/100-00000006 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4936 session_inv_on_tsx_state_changed:  Nothing delayed
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4180 session_on_tsx_state:  PJSIP/100-00000006 TSX State: Calling  Inv State: CALLING
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4184 session_on_tsx_state:  Topology: Pending:  <0:audio-0:audio:sendrecv (ulaw|alaw)>  Active: (null topology)
[Mar 29 01:48:24] DEBUG[789]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 29 01:48:24] DEBUG[789]: chan_pjsip.c:2382 call:  RC: 0

And here is another one:

[Mar 28 20:44:46] DEBUG[685]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f6c280e1a48 for Request msg CANCEL/cseq=21 (rdata0x7f6bd0013908)
[Mar 28 20:44:46] DEBUG[685]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000042 associated with dialog dlg0x7f6c280e1a48
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/8006-00000002 TSX State: Trying  Inv State: INCOMING
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4413 handle_incoming_request:  PJSIP/8006-00000002: Method is CANCEL
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4423 handle_incoming_request:  PJSIP/8006-00000002
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4936 session_inv_on_tsx_state_changed:  Nothing delayed
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/8006-00000002 TSX State: Completed  Inv State: INCOMING
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4936 session_inv_on_tsx_state_changed:  Nothing delayed
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4180 session_on_tsx_state:  PJSIP/8006-00000002 TSX State: Completed  Inv State: INCOMING
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4184 session_on_tsx_state:  Topology: Pending:  <0:audio-0:audio:sendrecv (alaw|ulaw|speex|opus)>  Active: (null topology)
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4630 session_inv_on_state_changed:  PJSIP/8006-00000002 Event: TSX_STATE  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4656 session_inv_on_state_changed: PJSIP/8006-00000002: Source of transaction state change is TX_MSG
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4704 session_inv_on_state_changed:  
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  PJSIP/8006-00000002 TSX State: Completed  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4770 session_inv_on_tsx_state_changed:  Disconnected
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4180 session_on_tsx_state:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4180 session_on_tsx_state:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2975 chan_pjsip_session_end:  PJSIP/8006-00000002
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2992 chan_pjsip_session_end:  
[Mar 28 20:44:46] DEBUG[676]: cdr.c:1473 cdr_object_finalize: Finalized CDR for PJSIP/8006-00000002 - start 1648493075.641237 answer 0.000000 end 1648493086.399078 dur 10.757 bill 1648493086.399 dispo NO ANSWER
[Mar 28 20:44:46] DEBUG[784][C-00000002]: app_dial.c:1787 wait_for_answer:  PJSIP/8006-00000002: Caller hung up
[Mar 28 20:44:46] DEBUG[784][C-00000002]: channel.c:2549 ast_hangup: Channel 0x7f6c8800abd0 'PJSIP/100-00000003' hanging up.  Refs: 2
[Mar 28 20:44:46] DEBUG[784][C-00000002]: chan_pjsip.c:2522 chan_pjsip_hangup:  PJSIP/100-00000003
[Mar 28 20:44:46] DEBUG[784][C-00000002]: chan_pjsip.c:2540 chan_pjsip_hangup:  Cause: 500
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2489 hangup:  PJSIP/100-00000003
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:3456 ast_sip_session_terminate:  PJSIP/100-00000003 Response 500
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:3528 ast_sip_session_terminate:  
[Mar 28 20:44:46] DEBUG[686]: channel.c:2196 ast_channel_destructor: Channel 0x7f6c8800abd0 'PJSIP/100-00000003' destroying
[Mar 28 20:44:46] DEBUG[784][C-00000002]: app_dial.c:3429 dial_exec_full: Exiting with DIALSTATUS=CANCEL.
[Mar 28 20:44:46] DEBUG[784][C-00000002]: app_dial.c:3460 dial_exec_full:  PJSIP/8006-00000002: Done
[Mar 28 20:44:46] DEBUG[784][C-00000002]: pbx.c:4435 __ast_pbx_run: Spawn extension (default,100,1) exited non-zero on 'PJSIP/8006-00000002'
[Mar 28 20:44:46]   == Spawn extension (default, 100, 1) exited non-zero on 'PJSIP/8006-00000002'
[Mar 28 20:44:46] DEBUG[784][C-00000002]: channel.c:2459 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/8006-00000002'
[Mar 28 20:44:46] DEBUG[676]: cdr.c:1473 cdr_object_finalize: Finalized CDR for PJSIP/100-00000003 - start 1648493075.641924 answer 0.000000 end 1648493086.399158 dur 10.757 bill 1648493086.399 dispo NO ANSWER
[Mar 28 20:44:46] DEBUG[676]: cdr.c:1313 cdr_object_create_public_records: CDR for PJSIP/100-00000003 is dialed and has no Party B; discarding
[Mar 28 20:44:46] DEBUG[784][C-00000002]: channel.c:2549 ast_hangup: Channel 0x7f6c280133d0 'PJSIP/8006-00000002' hanging up.  Refs: 2
[Mar 28 20:44:46] DEBUG[686]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1648493075.4, detail: 
[Mar 28 20:44:46] DEBUG[784][C-00000002]: chan_pjsip.c:2522 chan_pjsip_hangup:  PJSIP/8006-00000002
[Mar 28 20:44:46] DEBUG[686]: stasis.c:451 topic_dtor: Topic 'channel:1648493075.4': 0x7f6c8800b810 destroyed
[Mar 28 20:44:46] DEBUG[686]: channel_internal_api.c:680 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[Mar 28 20:44:46] DEBUG[686]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2513 hangup:  
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2489 hangup:  PJSIP/8006-00000002
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:3456 ast_sip_session_terminate:  PJSIP/8006-00000002 Response 500
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:3528 ast_sip_session_terminate:  
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:2912 session_destructor: 8006: Destroying SIP session
[Mar 28 20:44:46] DEBUG[784][C-00000002]: chan_pjsip.c:2540 chan_pjsip_hangup:  Cause: 500
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7f6c28064950) DTLS srtp - stopped timeout timer'
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7f6c28064950) DTLS srtp - stopped timeout timer'
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:2275 ast_rtp_dtls_stop: (0x7f6c28064950) DTLS stop
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7f6c28064950) DTLS srtp - stopped timeout timer'
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:2873 dtls_srtp_stop_timeout_timer: (0x7f6c28064950) DTLS srtp - stopped timeout timer'
[Mar 28 20:44:46] DEBUG[686]: res_rtp_asterisk.c:3981 rtp_deallocate_transport: (0x7f6c28064950) ICE RTP transport deallocating
[Mar 28 20:44:46] DEBUG[686]: rtp_engine.c:455 instance_destructor: Destroyed RTP instance '0x7f6c28064950'
[Mar 28 20:44:46] DEBUG[686]: channel.c:2196 ast_channel_destructor: Channel 0x7f6c280133d0 'PJSIP/8006-00000002' destroying
[Mar 28 20:44:46] DEBUG[686]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1648493075.3, detail: 
[Mar 28 20:44:46] DEBUG[676]: stasis.c:580 stasis_topic_create_with_detail: Creating topic. name: channel:1648493086.5, detail: 
[Mar 28 20:44:46] DEBUG[686]: stasis.c:451 topic_dtor: Topic 'channel:1648493075.3': 0x7f6c280d1130 destroyed
[Mar 28 20:44:46] DEBUG[676]: stasis.c:614 stasis_topic_create_with_detail: Topic 'channel:1648493086.5': 0x7f6c4c0047a0 created
[Mar 28 20:44:46] DEBUG[676]: stasis.c:442 topic_dtor: Destroying topic. name: channel:1648493086.5, detail: 
[Mar 28 20:44:46] DEBUG[686]: channel_internal_api.c:680 ast_channel_nativeformats_set:  <initializing>: MultistreamFormats: (nothing)
[Mar 28 20:44:46] DEBUG[676]: stasis.c:451 topic_dtor: Topic 'channel:1648493086.5': 0x7f6c4c0047a0 destroyed
[Mar 28 20:44:46] DEBUG[686]: channel_internal_api.c:692 ast_channel_nativeformats_set:  Channel is being initialized or destroyed
[Mar 28 20:44:46] DEBUG[686]: chan_pjsip.c:2513 hangup:  
[Mar 28 20:44:46] DEBUG[668]: devicestate.c:466 do_state_change: Changing state for PJSIP/100 - state 1 (Not in use)
[Mar 28 20:44:46] DEBUG[668]: devicestate.c:466 do_state_change: Changing state for PJSIP/8006 - state 1 (Not in use)
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4760 session_inv_on_tsx_state_changed:  Session ended
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4180 session_on_tsx_state:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 28 20:44:46] DEBUG[685]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f6c280e1a48 for Request msg ACK/cseq=21 (rdata0x7f6bd0013908)
[Mar 28 20:44:46] DEBUG[685]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000042 to use for Request msg ACK/cseq=21 (rdata0x7f6bd0013908)
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_endpoint_identifier_ip.c:275 common_identify: No identify sections to match against
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '8006' domain 'xxxxxx.net'
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '8006' domain 'xxxxxxxx.net'
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  (null session) TSX State: Confirmed  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4760 session_inv_on_tsx_state_changed:  Session ended
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4180 session_on_tsx_state:  (null session) TSX State: Confirmed  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[686]: res_pjsip_session.c:4189 session_on_tsx_state:  
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4748 session_inv_on_tsx_state_changed:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4760 session_inv_on_tsx_state_changed:  Session ended
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4180 session_on_tsx_state:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Mar 28 20:44:46] DEBUG[685]: res_pjsip_session.c:4189 session_on_tsx_state:

And here one without debug:

[Mar 30 17:52:14]     -- Executing [100@default:1] Dial("PJSIP/009-00000003", "PJSIP/100/sip:s2b2k9qb@10.0.0.70:55097;transport=ws&PJSIP/100/sip:8ut0b7g7@10.0.0.70:55095;transport=ws&PJSIP/100/sip:5ehpe7fp@10.0.0.70:55096;transport=ws&PJSIP/100/sip:o7l7tecj@10.0.0.70:55093;transport=ws&PJSIP/100/sip:84qora44@10.0.0.70:55092;transport=ws&PJSIP/100/sip:k9nfnr07@10.0.0.70:55094;transport=ws") in new stack
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:s2b2k9qb@10.0.0.70:55097;transport=ws
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:8ut0b7g7@10.0.0.70:55095;transport=ws
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:5ehpe7fp@10.0.0.70:55096;transport=ws
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:o7l7tecj@10.0.0.70:55093;transport=ws
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:84qora44@10.0.0.70:55092;transport=ws
[Mar 30 17:52:14]     -- Called PJSIP/100/sip:k9nfnr07@10.0.0.70:55094;transport=ws
[Mar 30 17:52:14]     -- PJSIP/100-00000004 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:14]     -- PJSIP/100-00000008 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:14]     -- PJSIP/100-00000006 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:14]     -- PJSIP/100-00000009 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:14]     -- PJSIP/100-00000005 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:14]     -- PJSIP/100-00000007 connected line has changed. Saving it until answer for PJSIP/009-00000003
[Mar 30 17:52:29]   == Spawn extension (default, 100, 1) exited non-zero on 'PJSIP/009-00000003'

Does anybody know what the issue could be? @nanosonde @felipecrs any ideas?

nanosonde commented 2 years ago

Maybe it also makes sense to watch the browser console for the cards messages. Also the webrtc diagnose page from chrome would be helpful.

nanosonde commented 2 years ago

Are those people using NAT? Is a STUN server configured in rtp.conf? Maybe also a SIP trace would be helpful: pjsip logger set on

TECH7Fox commented 2 years ago

Will ask for the webrtc debug and pjsip trace.

They do use stun, they got the latest add-on configuration.

TECH7Fox commented 2 years ago

They don't get anything, seems like Asterisk doesn't even try to reach it. Here is a picture:

https://media.discordapp.net/attachments/927579367855521812/959360626575171664/unknown.png

And here is the full log: https://cdn.discordapp.com/attachments/927579367855521812/959361779790671912/message.txt

With the Asterisk log:

[Apr  1 09:59:35]     -- Called PJSIP/100/sip:7ofoqh81@82.146.119.172:30309;transport=ws
[Apr  1 10:00:07]   == Everyone is busy/congested at this time (1:0/0/1)
[Apr  1 10:00:07]     -- Auto fallthrough, channel 'PJSIP/6001-00000002' status is 'CHANUNAVAIL'
TECH7Fox commented 2 years ago

Here are logs with the pjsip trace.

https://cdn.discordapp.com/attachments/927579367855521812/960210654608916511/message.txt

https://cdn.discordapp.com/attachments/927579367855521812/960241757935767642/PJSIP_log.txt

Both give a 503 service unavailable.

pergolafabio commented 2 years ago

@nanosonde , any clue? this log was mine:

https://cdn.discordapp.com/attachments/927579367855521812/960210654608916511/message.txt

the card i use with duckdns and a simple port forward for RTP and websocket 8099 Calling from card 100 to extension 6000/6001 works, but from 6000 or 6001 to 100 doesnt nothing to see in the f12 developer logs, it just looks like the endpoint can be found

this is my config

[transport-udp]
type = transport
protocol = udp
bind=0.0.0.0:5050
local_net=192.168.0.0/24
local_net=10.8.0.0/24
local_net=172.30.32.0/24
external_media_address=mydomain.com
external_signaling_address=mydomain.com

[transport-wss]
type=transport
protocol=wss
bind=0.0.0.0
local_net=192.168.0.0/24
local_net=10.8.0.0/24
local_net=172.30.32.0/24
external_media_address=mydomain.com
external_signaling_address=mydomain.com

[6000]
type=endpoint
context=default
disallow=all
allow=ulaw,alaw
allow=h264,vp8
auth=auth6000
aors=6000
rtp_symmetric=yes
force_rport=yes
rewrite_contact=yes
direct_media=no

[auth6000]
type=auth
auth_type=userpass
password=blabla
username=6000

[6000]
type=aor
qualify_frequency=60
max_contacts=1
remove_existing=yes
remove_unavailable=yes

i also tried copy/pasting @TECH7Fox his config, and then i have the same issue

pergolafabio commented 2 years ago

@nanosonde , your comment is gone?

yes, i ue the addon, ICE is there:

[general]
rtpstart=10000
rtpend=20000
icesupport=yes
stunaddr=stun.l.google.com:19302

i also use it in card config:

            iceTimeout: 3
            iceConfig:
              iceCandidatePoolSize: 0
              iceTransportPolicy: all
              iceServers:
                - urls:
                    - stun:stun.l.google.com:19302
                    - stun:stun1.l.google.com:19302

But with or without, doesnt make any difference :-(

pergolafabio commented 2 years ago

I think the extension is just unreachable, remember we disabled qualify when i turn qualify back to 60 sec, as soon as i register a websocket extension , it becomes immediately "Unreachable"

[Apr  4 14:09:03]     -- Added contact 'sip:pglm7aco@192.168.0.1:5613;transport=ws' to AOR '102' with expiration of 600 seconds
[Apr  4 14:09:06]     -- Contact 102/sip:pglm7aco@192.168.0.1:5613;transport=ws is now Unreachable.  RTT: 0.000 msec

i just created an extra wss endpoint for 102 in the pjsip_custom file, where i enabled qualify back to 60

PS/ whats also , strange, why is there 192.168.0.1 in the above log, thats my router .... shouldnt that be the public ip? its quite normal that 192.168.0.1:5613 is not reachable...

EDIT: when i go mobile with android instead of browser, then i see my public IP

[Apr  4 14:20:06]     -- Added contact 'sip:b7dl7au3@178.144.xx.xx:59475;transport=ws' to AOR '102' with expiration of 600 seconds
[Apr  4 14:20:09]     -- Contact 102/sip:b7dl7au3@178.144.xx.xx:59475;transport=ws is now Unreachable.  RTT: 0.000 msec

But as you can see, goes immediately unreachable, ... thats why it cant be called...

TECH7Fox commented 2 years ago

@pergolafabio here is my logs.

Local, but set the host as my external duckdns address. From hardphone to card.

pjsipTrace.txt

pergolafabio commented 2 years ago

Hey, what happens if you turn on qualify , do you see the wss extensions still reachable ? I copied over the wss extensions to the custom file, so it doesnt get overwritten...

Mine are always unreachable after 2 sec after the register, so I think that's the reason that I can't call them... But why...

pergolafabio commented 2 years ago

@TECH7Fox as requested the info you wanted :

Global Settings:

 ParameterName                              : ParameterValue
 ======================================================================
 contact_expiration_check_interval          : 30
 debug                                      : no
 default_from_user                          : asterisk
 default_outbound_endpoint                  : default_outbound_endpoint
 default_realm                              : asterisk
 default_voicemail_extension                :
 disable_multi_domain                       : false
 endpoint_identifier_order                  : ip,username,anonymous
 ignore_uri_user_options                    : false
 keep_alive_interval                        : 90
 max_forwards                               : 70
 max_initial_qualify_time                   : 0
 mwi_disable_initial_unsolicited            : false
 mwi_tps_queue_high                         : 500
 mwi_tps_queue_low                          : -1
 norefersub                                 : yes
 regcontext                                 :
 send_contact_status_on_update_registration : no
 taskprocessor_overload_trigger             : global
 unidentified_request_count                 : 5
 unidentified_request_period                : 5
 unidentified_request_prune_interval        : 30
 use_callerid_contact                       : no
 user_agent                                 : Asterisk PBX 18.10.1

System Settings:

 ParameterName               : ParameterValue
 ============================================
 accept_multiple_sdp_answers : false
 compact_headers             : false
 disable_rport               : false
 disable_tcp_switch          : true
 follow_early_media_fork     : true
 threadpool_auto_increment   : 5
 threadpool_idle_timeout     : 60
 threadpool_initial_size     : 0
 threadpool_max_size         : 50
 timer_b                     : 32000
 timer_t1                    : 500

3e533915-asterisk*CLI> pjsip show aor 100

      Aor:  <Aor..............................................>  <MaxContact>
    Contact:  <Aor/ContactUri............................> <Hash....> <Status> <RTT(ms)..>
==========================================================================================

      Aor:  100                                                  6

 ParameterName        : ParameterValue
 =====================================
 authenticate_qualify : false
 contact              :
 default_expiration   : 3600
 mailboxes            :
 max_contacts         : 6
 maximum_expiration   : 7200
 minimum_expiration   : 60
 outbound_proxy       :
 qualify_frequency    : 0
 qualify_timeout      : 3.000000
 remove_existing      : true
 remove_unavailable   : true
 support_path         : false
 voicemail_extension  :
TECH7Fox commented 2 years ago

Thanks, it looks excactly the same for me as expected. Except for the contact of course.

This bug is really weird. Think we should ask the Asterisk community for help.

I also thought about adding the older version of the add-on with chan_sip to the repo.

Also, these could be helpful:

Will look into it some more this week. Hope we can fix it soon.

pergolafabio commented 2 years ago

Yes, it's really weird, more and more people have the issue it seems, will also have a look on forums

pergolafabio commented 2 years ago

The first thread you posted is interesting , what does he mean by :

I took a closer look to the way I handled OPTIONS and saw I wasn’t properly using the branch from the Options request in the Via header of the response. The Contact is now reachable:

pergolafabio commented 2 years ago

as suggested, i reverted back to old card 1.0.1 , there i saw error below again

image

That leaded me to :

https://community.asterisk.org/t/webrtc-two-servers-registered-but-unavailable-only-one-one/91631/2

_I finally found the problem. I finally noticed the “sip.Parser | error parsing header ‘From’” in the browser console. When I used the ‘from_domain’ option in the endpoint then it worked. By default the From in Asterisk uses the hostname. The problem came from the naming scheme on our production servers have leading digits. Even though, in my opinion, these are correct hostnames, SIP.js doesn’t like it. If I use the ‘fromdomain’ to change it to anything without a leading digit then it works. The working systems just happened to have hostnames without leading digits.

so after adding the from_domain on the webrtc endpoints, it finally worked!!!

like below for example:

; Common ENDPOINT parameters (template)
[sipjs-phone-endpoint](!) 
type=endpoint
send_rpid=yes
send_pai=yes
device_state_busy_at=1
webrtc=yes
from_domain=asterisk
; Setting webrtc=yes is a shortcut for setting the following options:
; use_avpf=yes
; media_encryption=dtls
; dtls_auto_generate_cert=yes (if dtls_cert_file is not set)
; dtls_verify=fingerprint
; dtls_setup=actpass
; ice_support=yes
; media_use_received_transport=yes
; rtcp_mux=yes
rtp_symmetric=yes
force_rport=yes
rewrite_contact=yes
direct_media=no
context=default
disallow=all
allow=ulaw,alaw,speex,gsm,g726,g723,g722,opus
nanosonde commented 2 years ago

I also thought about adding the older version of the add-on with chan_sip to the repo.

Do you really want to go back to chan_sip?

pergolafabio commented 2 years ago

not needed anymore, its fixed now seems the cause was the hostname of the addon, its not allowed to start by digits for asterisk

@nanosonde , in my case the addon was named : 3e533915-asterisk seems thats not allowed @TECH7Fox his addon was named : b35499aa-asterisk

thats why he didnt notice the issue, and some users did

nanosonde commented 2 years ago

According to this more recent RFC a hostname starting with a digit is valid: https://www.rfc-editor.org/rfc/rfc1123#page-13

In the older RFC-952 this was initially specified to be a letter only for the first character.

Anyway, good finding! 👍🏻

So does asterisk needs to fixed here?

pergolafabio commented 2 years ago

So what RFC this addon is based on? Yes, PR already submitted, it's working now

TECH7Fox commented 2 years ago

Do you really want to go back to chan_sip?

Was a idea to test and compare, but it's already fixed.

So does asterisk needs to fixed here?

I guess so, seems like a neasty bug.