ASTERISK-25229: Exchanging Device and Mailbox State Using PJSIP fails after restart of peer

[Home]

Summary: ASTERISK-25229: Exchanging Device and Mailbox State Using PJSIP fails after restart of peer

Reporter: Vadim (cron333) Labels:

Date Opened: 2015-07-03 09:25:27 Date Closed:

Priority: Major Regression?

Status: Open/New Components: Resources/res_pjsip Resources/res_pjsip_publish_asterisk

Versions: 13.4.0 13.5.0 Frequency of
Occurrence Constant

Related
Issues:

Environment: CentOS-7 x86_64 Attachments: ( 0) debug.txt
( 1) DebugPJSIP.txt
( 2) PJSIP_dump_1.txt
( 3) pjsip_outbound_publish_412.patch
( 4) pjsip_outbound_publish_debug.patch
( 5) pjsip.log
( 6) ServA.txt
( 7) ServA-172.16.2.14.txt
( 8) ServA-172.16.2.14.txt
( 9) ServB.txt
(10) ServB-172.16.2.15.txt
(11) ServB-172.16.2.15.txt
(12) Снимок_экрана_2015-07-16_в_0.17.47.png

Description: There are two servers: "A" and "B".
When we restart "Asterisk" on "A" we will see in the console of "B":
[Jul 3 14:17:13] WARNING[17452]: res_pjsip_outbound_authenticator_digest.c:135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
After this "B' can't share a device state to "A", but "A" to "B" can.
If we restart "Asterisk" on the server "B", the server "A" will not be able to share a device state to "B", but "B" to "A" can.

The configuration, that has been used: https://wiki.asterisk.org/wiki/display/AST/Exchanging+Device+and+Mailbox+State+Using+PJSIP?showComments=true

Comments: By: Asterisk Team (asteriskteam) 2015-07-03 09:25:29.344-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Rusty Newton (rnewton) 2015-07-06 12:57:57.522-0500

Please provide:

* Asterisk versions for both systems.
* Asterisk logs demonstrating the issue[1] - including verbose and debug. For both systems.

[1]: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information
By: Vadim (cron333) 2015-07-09 07:56:03.646-0500

Asterisk 13.4.0 on both systems

A: 192.168.1.146
B: 192.168.1.148

On both: SIP-port: 5060, PJSIP-port: 5071

B - service asterisk restart

In the console of A: "[Jul 9 15:06:14] WARNING[14301]: res_pjsip_outbound_authenticator_digest.c:135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
[Jul 9 15:06:14] WARNING[14301]: res_pjsip_outbound_authenticator_digest.c:135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge."

Call through the server A (from 111 to 1001)

The console of B is empty! ('core set debug 5', 'pjsip set logger on')

The debug_log of A is in the attached file.

From B to A the exchange of the device state is correct.

Debug A:

[Edit by Rusty - Removed debug log as per the guidelines. Please follow the guidelines]
By: Rusty Newton (rnewton) 2015-07-09 19:13:50.174-0500

Attaching reporter's debug log after removing it from the previous comment.
By: Mark Michelson (mmichelson) 2015-07-10 09:29:39.255-0500

I don't see the warning messages in A's debug. What you've attached only goes as late as 14:53 on July 9, but the warning you copied into your comment says it happened at 15:06. Did some of the debug log get cut off?
By: Mark Michelson (mmichelson) 2015-07-10 09:34:00.912-0500

Oh, and another data point: can we see the pjsip.conf files for the A and B boxes? I know you pointed to the example wiki page, but that wiki page has no authentication configured. So I would be interested in seeing what you have for in your pjsip.conf file. With the pjsip.conf file and the PJSIP debug that apparently was cut off from the previously posted debug log, we can see potentially why there are issues with regards to authentication realm.
By: Vadim (cron333) 2015-07-10 10:04:43.503-0500

Sorry, i'll send a new debug log a little bit later ...
By: Vadim (cron333) 2015-07-13 08:59:53.721-0500

i did the same situation: the call from 111 to 1001 (on the server A)

P. S. CLI>logger add channel myDebugLog notice,warning,error,debug,verbose,dtmf
By: Rusty Newton (rnewton) 2015-07-15 15:46:28.679-0500

Same issue with the new debug logs. I don't see the WARNING that you mentioned.

On the CLI you can see what log types are going where with "logger show channels"

After you get settings how you need, makes sure to run "logger reload" and "logger rotate". Verify the logs contain what you expect to be there before posting them.
By: Vadim (cron333) 2015-07-15 16:29:10.199-0500

I don't see the WARNING messages also ...
By: Rusty Newton (rnewton) 2015-07-16 15:53:13.758-0500

I want to clarify...

Despite the WARNING's apparently not occurring.. does the problem still occur, that device and mailbox state is not exchanged?
By: Vadim (cron333) 2015-07-17 03:28:20.395-0500

yes, exactly, as it's written above ...

If restart the asterisk on "A" after the restart (asterisk) on "B", "A" will exchange to "B", but "B" will not! And if restart the asterisk on 'B" after the restart on "A", "B" will exchange to "A", but "A" will not. (for the current settings of the pjsip)
By: Rusty Newton (rnewton) 2015-08-24 09:59:33.411-0500

Thanks for all the detail.

I was able to reproduce the issue by stopping and starting one Asterisk instance from the CLI. After it came back up, the other instance would no longer publish state, yet the instance that was just started back would continue to publish state. There was at least one time where this issue didn't occur. There must be some aspect of timing involved.

By: Alexei Gradinari (alexei gradinari) 2016-02-05 11:57:08.149-0600

Asterisk 'A' receives a 412 (Conditional Request Failed) response from restarted Asterisk 'B'.
Asterisk 'A' has to recreate publish session.
There is bug in res_pjsip_outbound_publish.c
The function sip_outbound_publish_client_alloc is called with wrong object while processing 412 code.
This patch fixes it.

By: Alexei Gradinari (alexei gradinari) 2016-02-05 12:27:23.188-0600

Debug if could not send message.

By: Tolmachev Ivan (tol_iwan) 2016-02-10 01:35:20.660-0600

I installed the patch.
I tried with asterisk 13.7.0 and 13.7.2.
Overloads the "A". On the "B" I get
res_pjsip_outbound_authenticator_digest.c: 135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
"B" does not send condition "A". "A" sends the status to "B".
Overloads the "B". Reversed.
The patch does not work?
By: Alexei Gradinari (alexei gradinari) 2016-02-10 09:47:34.597-0600

This patch works in my configuration (without auth between asterisks).
Can you check it without auth?
By: Tolmachev Ivan (tol_iwan) 2016-02-10 23:51:27.829-0600

Configuration matches the specified ServA.txt and ServA.txt. The difference in the IP-address and port.
Do I understand that in this configuration, no Auth?
Auth only use for endpoint inside asterisk.
Now try again to install the patch and the asterisk. Maybe I missed something.
By: Tolmachev Ivan (tol_iwan) 2016-02-11 05:13:47.334-0600

Reinstall.
Asterisk 13.7.2
I do on the "A" "core restart now".
On the "B" message, too:
WARNING [27742]: res_pjsip_outbound_authenticator_digest.c: 135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
"B" does not send status to the "A"
By: Alexei Gradinari (alexei gradinari) 2016-02-11 09:16:06.704-0600

Is there only one transport in your configuration which used both for endpoints and asterisk peers?
Can you check with different transports.

For example:
[transport-udp] ;
type=transport
protocol=udp
bind=0.0.0.0:5071

[transport-peer];
type=transport
protocol=udp
bind=0.0.0.0:5090

[instance2]
type=endpoint
transport=transport-peer

[instance1]
type=endpoint
transport=transport-peer

By: Alexei Gradinari (alexei gradinari) 2016-02-11 09:19:59.397-0600

Are you sure you patched asterisk with pjsip_outbound_publish_412.patch?
Can you capture traffic between asterisk peers?
By: Tolmachev Ivan (tol_iwan) 2016-02-12 00:26:44.434-0600

Laid pjsip.log file
Initial conditions:
1. ServA 172.16.2.14, ServB 172.16.2.15
2. 780 - phone on Serva, 785 - phone on ServB
3. Both asterisk stopped.

Run:
1. ServA asterisk start.
2. ServA - CLI
3. ServA - sip set debug ip 172.16.2.15
4. ServA - pjsip set logger host 172.16.2.15
5. ServB asterisk start.
6. Status device ServA <-> ServB OK
7. ServB asterisk stop.
8. ServB asterisk start.
9. Status device ServA <- ServB OK
10. Status device ServA -> ServB FAIL

Message
WARNING [1776]: res_pjsip_outbound_authenticator_digest.c: 135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
occurs when "ServB asterisk start".
This message does not appear, if in step:
6. Status device ServA <-> ServB OK
6.1 The device is switched off 785
7. ServB asterisk stop.
8. ServB asterisk start.
In this case all the same:
9. Status device ServA <- ServB OK
10. Status device ServA -> ServB FAIL
By: Tolmachev Ivan (tol_iwan) 2016-02-12 00:31:10.284-0600

Before installing Asterisk:
pjsip_outbound_publish_412.patch
pjsip_outbound_publish_debug.patch
File "res_pjsip_outbound_publish.c" changed.
By: Tolmachev Ivan (tol_iwan) 2016-02-12 05:20:38.099-0600

Files pjsip.conf completely:
- ServA-172.16.2.14.txt
- ServB-172.16.2.15.txt
By: Tolmachev Ivan (tol_iwan) 2016-02-12 06:13:32.793-0600

You can show your pjsip.conf and extensions.conf? Where it works.
By: Alexei Gradinari (alexei gradinari) 2016-02-12 09:49:02.824-0600

I think restarted asterisk sends '401 Unauthorized' because it treats another asterisk peer as endpoint-local.

You should set different transports for peers and endpoint-local.
I modified your configs, see attachments.
Could, you, please, test it with these configs.

By: Alexei Gradinari (alexei gradinari) 2016-02-12 09:54:51.448-0600

My modified configs affected by another bug ASTERISK-25316.
Could you, please, change the order of transport in configuration files.
1st transport-peer, then transport-udp
The last one will used for qualifying endpoint-local

By: Alexei Gradinari (alexei gradinari) 2016-02-12 10:00:56.903-0600

Another solution - identify peer by ip-address to avoid auth.

; on ServA
[instance2]
type=identify
endpoint=instance2
match=172.16.2.15

; on ServB
[instance1]
type=identify
endpoint=instance1
match=172.16.2.14

By: Tolmachev Ivan (tol_iwan) 2016-02-16 01:34:16.608-0600

No changes.
I tried:
1c. your configuration
2. Swaps the 1st transport-peer, then transport-udp
3. Add the section [identify]
4. Moved rooms 780 and 785 on the SIP. In PJSIP left only instance.
There are no results.
It is possible to check whether the patch became asterisk?
By: Alexei Gradinari (alexei gradinari) 2016-02-16 10:28:31.077-0600

What version of pjproject is asterisk compiled with?
By: Tolmachev Ivan (tol_iwan) 2016-02-16 10:33:15.046-0600

http://www.pjsip.org/
2.4.5
By: Alexei Gradinari (alexei gradinari) 2016-02-16 10:42:58.468-0600

I use https://github.com/asterisk/pjproject
which is 2.4 version with patches for asterisk
By: Tolmachev Ivan (tol_iwan) 2016-02-16 10:48:14.119-0600

OK. Tomorrow will set
By: Tolmachev Ivan (tol_iwan) 2016-02-17 03:26:10.207-0600

Hi!
Install https://github.com/asterisk/pjproject.
No changes.

On solved the problem.
For convenience, I add a number of tests on 781 ServA.
For convenience, I add a number of tests on 784 ServB.
ServA:
instead
[Instance2]
type = asterisk-publication
devicestate_publish = instance2-devicestate
device_state = yes

used
[Instance2]
type = asterisk-publication
devicestate_publish = instance2-devicestate
device_state = yes
ServB: similarly.
Now ServB "core restart now".
ServA:
780 @ default: PJSIP / 780 State: Idle
servB:
780 @ default: PJSIP / 780 State: Unavailable
Do call 781-> 780.
ServA:
780 @ default: PJSIP / 780 State: Ringing
servB:
780 @ default: PJSIP / 780 State: Ringing
Further, there is no problem with the status.
But!
Periodically ServB:
WARNING [23432]: res_pjsip_pubsub.c: 2968 pubsub_on_rx_publish_request: No registered publish handler for event presence
Two questions:
Why is the problem so decided?
Why do I get WARNING?
By: Alexei Gradinari (alexei gradinari) 2016-02-17 09:19:20.857-0600

Can you clarify what resolved your problem?
The parts of configs "instead" and "used" are the same.

About
"780 @ default: PJSIP / 780 State: Unavailable"
It's normal, because after start ServB knows nothing about 780.
When status changes on ServA it's propagated to ServB and ServB changes status for 780.

About
WARNING [23432]: res_pjsip_pubsub.c: 2968 pubsub_on_rx_publish_request: No registered publish handler for event presence
May be this warning about Mailbox state.
If you don't want to exchange Mailbox states you should add
mailbox_state=no

By: Tolmachev Ivan (tol_iwan) 2016-02-17 23:14:51.250-0600

I'm sorry.
ServA:
instead
[Instance2]
type = asterisk-publication
*devicestate_publish = instance2-devicestate*
device_state = yes
used
[Instance2]
type = asterisk-publication
*devicestate_publish = instance2*
device_state = yes
ServB: similarly.
By: Tolmachev Ivan (tol_iwan) 2016-02-18 06:36:00.863-0600

WARNING [23432]: res_pjsip_pubsub.c: 2968 pubsub_on_rx_publish_request: No registered publish handler for event presence
I switch off the phone option "send status". Messages ceased.
Thank you.
By: Tolmachev Ivan (tol_iwan) 2016-02-18 06:36:42.806-0600

When the patch is included in the release?
By: Richard Mudgett (rmudgett) 2016-02-22 09:41:47.328-0600

Patch was merged.
By: Vadim (cron333) 2016-03-18 16:03:00.784-0500

Sorry, but the situation persists ...

When we are executing a command 'service asterisk restart' on the server A (ex., CentOS), on the console of the server B appears the message: 'res_pjsip_outbound_authenticator_digest.c:135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge' - and all repeats

But, if we stop both servers and then start them - everything works.
Or, if we stop the one server, and start it after a while (from one to several minutes) - everything works also. And the message doesn't appear on the console of the second server ...

By: Asterisk Team (asteriskteam) 2016-03-18 16:03:01.105-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Richard Mudgett (rmudgett) 2016-03-18 18:53:21.451-0500

[~cron333] The merged patch has not made it into a released version yet. It will be in v13.8.0. Are you using the tip of the v13 branch for your testing?
By: Vadim (cron333) 2016-03-19 04:12:18.135-0500

I'm using v.13.7.2 with the patch from here ...
By: Alexei Gradinari (alexei gradinari) 2016-03-21 13:53:44.333-0500

Vadim,
Сan you upload the current pjsip.conf files for both asterisk peers?
Can you capture SIP traffic between asterisk peers?
By: Vadim (cron333) 2016-03-22 01:43:42.497-0500

After A is restarted, B has not been sending the PUBLISH message to A. (only A -> B)
There is nothing to dump (tcpdump). PJSIP (pjsip set logger on) silent also.
The config-files i posted here already.
By: Alexei Gradinari (alexei gradinari) 2016-03-22 09:26:42.776-0500

Can you start tcpdump before restart A and stop after you get "Unable to create request with auth.No auth credentials for any realms in challenge."?
I need a whole config. You posted only part of config.

I use 2 transports:
1st for asterisk publications
2nd for endpoints

Do you use only one transport?
By: Alexei Gradinari (alexei gradinari) 2016-03-22 09:30:49.849-0500

Can you show
pjsip show endpoint instance1
on server B before and after restart serv A
By: Vadim (cron333) 2016-03-29 14:22:57.764-0500

>Can you start tcpdump before restart A and stop after you get "Unable to create request with auth.No auth credentials for any realms in challenge."?

In the attached file (PJSIP_dump_1.txt). tcpdump was started on the B with the command: "tcpdump -nn -s 0 host A -w /home/vadim/PJSIP_dump_1"

>I need a whole config. You posted only part of config.

It's the whole config ...

>Do you use only one transport?

I have tried both options (one transport and two transports) with the same result ... (when I was executing tcmpdump PJSIP had two transports (ports: 5071 and 5072). endpoints had the port 5072

>Can you show
>pjsip show endpoint instance1
>on server B before and after restart serv A

before:

pjsip show endpoint instance1:
{noformat}
=========================================================================================

Endpoint: instance1 Unknown 0 of inf
Transport: transport-ep udp 0 0 0.0.0.0:5072

ParameterName : ParameterValue
====================================================
100rel : yes
accountcode :
aggregate_mwi : true
allow : (nothing)
allow_subscribe : true
allow_transfer : true
aors :
auth :
call_group :
callerid : <unknown>
callerid_privacy : allowed_not_screened
callerid_tag :
connected_line_method : invite
context : default
cos_audio : 0
cos_video : 0
device_state_busy_at : 0
direct_media : true
direct_media_glare_mitigation : none
direct_media_method : invite
disable_direct_media_on_nat : false
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 : rfc4733
fax_detect : false
force_avp : false
force_rport : true
from_domain :
from_user :
g726_non_standard : false
ice_support : false
identify_by : username
inband_progress : false
language :
mailboxes :
media_address :
media_encryption : no
media_encryption_optimistic : false
media_use_received_transport : false
message_context :
moh_suggest : default
mwi_from_user :
named_call_group :
named_pickup_group :
one_touch_recording : false
outbound_auth :
outbound_proxy :
pickup_group :
record_off_feature : automixmon
record_on_feature : automixmon
rewrite_contact : false
rpid_immediate : 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_diversion : true
send_pai : false
send_rpid : false
set_var :
srtp_tag_32 : false
sub_min_expiry : 0
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-ep
trust_id_inbound : false
trust_id_outbound : false
use_avpf : false
use_ptime : false
user_eq_phone : false
{noformat}

after:
{noformat}
[Mar 29 22:19:12] WARNING[7846]: res_pjsip_outbound_authenticator_digest.c:135 digest_create_request_with_auth_from_old: Unable to create request with auth.No auth credentials for any realms in challenge.
{noformat}

pjsip show endpoint instance1:
{noformat}
=========================================================================================

Endpoint: instance1 Unknown 0 of inf
Transport: transport-ep udp 0 0 0.0.0.0:5072

ParameterName : ParameterValue
====================================================
100rel : yes
accountcode :
aggregate_mwi : true
allow : (nothing)
allow_subscribe : true
allow_transfer : true
aors :
auth :
call_group :
callerid : <unknown>
callerid_privacy : allowed_not_screened
callerid_tag :
connected_line_method : invite
context : default
cos_audio : 0
cos_video : 0
device_state_busy_at : 0
direct_media : true
direct_media_glare_mitigation : none
direct_media_method : invite
disable_direct_media_on_nat : false
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 : rfc4733
fax_detect : false
force_avp : false
force_rport : true
from_domain :
from_user :
g726_non_standard : false
ice_support : false
identify_by : username
inband_progress : false
language :
mailboxes :
media_address :
media_encryption : no
media_encryption_optimistic : false
media_use_received_transport : false
message_context :
moh_suggest : default
mwi_from_user :
named_call_group :
named_pickup_group :
one_touch_recording : false
outbound_auth :
outbound_proxy :
pickup_group :
record_off_feature : automixmon
record_on_feature : automixmon
rewrite_contact : false
rpid_immediate : 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_diversion : true
send_pai : false
send_rpid : false
set_var :
srtp_tag_32 : false
sub_min_expiry : 0
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-ep
trust_id_inbound : false
trust_id_outbound : false
use_avpf : false
use_ptime : false
user_eq_phone : false
{noformat}

By: Richard Mudgett (rmudgett) 2016-03-29 15:06:45.378-0500

[~cron333] Please do not paste configs and other large things into comments. Attach them as files instead.
By: Alexei Gradinari (alexei gradinari) 2016-03-29 18:18:55.231-0500

One of your server (172.31.17.48) is behind NAT
> Via: SIP/2.0/UDP 172.31.17.48:5072;rport=5072;received=52.29.123.238;branch=z9hG4bKPjb23c4846-ac5d-49db-a343-389c4633b883

Can you test without NAT?
By: Vadim (cron333) 2016-03-30 02:13:17.829-0500

>Can you test without NAT?

Unfortunately no. This is Amazon (AWS)

>One of your server (172.31.17.48) is behind NAT

Both servers are behind NAT (Full Cone NAT). They are both deployed on Amazon ...
By: Alexei Gradinari (alexei gradinari) 2016-03-30 09:05:05.525-0500

I think you should configure authentication between instance1 and instance2.