ASTERISK-29344: ami: Contact events getting dropped

[Home]

Summary: ASTERISK-29344: ami: Contact events getting dropped

Reporter: Brian J. Murrell (brian_j_murrell) Labels:

Date Opened: 2021-03-12 06:53:33.000-0600 Date Closed: 2021-04-06 12:00:01

Priority: Minor Regression? Yes

Status: Closed/Complete Components: Core/ManagerInterface Resources/res_pjsip_registrar

Versions: 18.2.2 Frequency of
Occurrence Occasional

Related
Issues:

Environment: Attachments:

Description: I am experiencing what seems to be dropped AMI events, in particular when and endpoint registers. This doesn't happen all of the time, maybe about 10-20% of the time.

Take for example this series of AMI events:

{noformat}
Thu Mar 11 19:15:06 EST 2021: Event: ChallengeSent
Thu Mar 11 19:15:06 EST 2021: Privilege: security,all
Thu Mar 11 19:15:06 EST 2021: Timestamp: 1615508106.775538
Thu Mar 11 19:15:06 EST 2021: SystemName: pbx.example.com
Thu Mar 11 19:15:06 EST 2021: EventTV: 2021-03-11T19:15:06.775-0500
Thu Mar 11 19:15:06 EST 2021: Severity: Informational
Thu Mar 11 19:15:06 EST 2021: Service: PJSIP
Thu Mar 11 19:15:06 EST 2021: EventVersion: 1
Thu Mar 11 19:15:06 EST 2021: AccountID: example_ep
Thu Mar 11 19:15:06 EST 2021: SessionID: hIZfJDMpqE
Thu Mar 11 19:15:06 EST 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Thu Mar 11 19:15:06 EST 2021: RemoteAddress: IPV4/TCP/10.75.22.32/50806
Thu Mar 11 19:15:06 EST 2021: Challenge:
Thu Mar 11 19:15:06 EST 2021:
Thu Mar 11 19:15:06 EST 2021: Event: SuccessfulAuth
Thu Mar 11 19:15:06 EST 2021: Privilege: security,all
Thu Mar 11 19:15:06 EST 2021: Timestamp: 1615508106.857175
Thu Mar 11 19:15:06 EST 2021: SystemName: pbx.example.com
Thu Mar 11 19:15:06 EST 2021: EventTV: 2021-03-11T19:15:06.857-0500
Thu Mar 11 19:15:06 EST 2021: Severity: Informational
Thu Mar 11 19:15:06 EST 2021: Service: PJSIP
Thu Mar 11 19:15:06 EST 2021: EventVersion: 1
Thu Mar 11 19:15:06 EST 2021: AccountID: example_ep
Thu Mar 11 19:15:06 EST 2021: SessionID: hIZfJDMpqE
Thu Mar 11 19:15:06 EST 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Thu Mar 11 19:15:06 EST 2021: RemoteAddress: IPV4/TCP/10.75.22.32/50806
Thu Mar 11 19:15:06 EST 2021: UsingPassword: 1
Thu Mar 11 19:15:06 EST 2021:
Thu Mar 11 19:15:06 EST 2021: Event: ContactStatus
Thu Mar 11 19:15:06 EST 2021: Privilege: system,all
Thu Mar 11 19:15:06 EST 2021: Timestamp: 1615508106.858452
Thu Mar 11 19:15:06 EST 2021: SystemName: pbx.example.com
Thu Mar 11 19:15:06 EST 2021: URI: sip:example_ep@10.75.22.32:50806;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1
Thu Mar 11 19:15:06 EST 2021: ContactStatus: NonQualified
Thu Mar 11 19:15:06 EST 2021: AOR: example_ep
Thu Mar 11 19:15:06 EST 2021: EndpointName: example_ep
{noformat}

We can see the endpoint being challenged and successfully authenticating followed by a ContactStatus event for the registration.

Yet in this example:
{noformat}
Thu Mar 11 14:15:06 EST 2021: Event: ChallengeSent
Thu Mar 11 14:15:06 EST 2021: Privilege: security,all
Thu Mar 11 14:15:06 EST 2021: Timestamp: 1615490106.969337
Thu Mar 11 14:15:06 EST 2021: SystemName: pbx.example.com
Thu Mar 11 14:15:06 EST 2021: EventTV: 2021-03-11T14:15:06.969-0500
Thu Mar 11 14:15:06 EST 2021: Severity: Informational
Thu Mar 11 14:15:06 EST 2021: Service: PJSIP
Thu Mar 11 14:15:06 EST 2021: EventVersion: 1
Thu Mar 11 14:15:06 EST 2021: AccountID: example_ep
Thu Mar 11 14:15:06 EST 2021: SessionID: hIZfJDMpqE
Thu Mar 11 14:15:06 EST 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Thu Mar 11 14:15:06 EST 2021: RemoteAddress: IPV4/TCP/10.75.22.32/50328
Thu Mar 11 14:15:06 EST 2021: Challenge:
Thu Mar 11 14:15:06 EST 2021:
Thu Mar 11 14:15:07 EST 2021: Event: SuccessfulAuth
Thu Mar 11 14:15:07 EST 2021: Privilege: security,all
Thu Mar 11 14:15:07 EST 2021: Timestamp: 1615490107.013907
Thu Mar 11 14:15:07 EST 2021: SystemName: pbx.example.com
Thu Mar 11 14:15:07 EST 2021: EventTV: 2021-03-11T14:15:07.013-0500
Thu Mar 11 14:15:07 EST 2021: Severity: Informational
Thu Mar 11 14:15:07 EST 2021: Service: PJSIP
Thu Mar 11 14:15:07 EST 2021: EventVersion: 1
Thu Mar 11 14:15:07 EST 2021: AccountID: example_ep
Thu Mar 11 14:15:07 EST 2021: SessionID: hIZfJDMpqE
Thu Mar 11 14:15:07 EST 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Thu Mar 11 14:15:07 EST 2021: RemoteAddress: IPV4/TCP/10.75.22.32/50328
Thu Mar 11 14:15:07 EST 2021: UsingPassword: 1
{noformat}

There is the challenge and authentication events but no ContactStatus event. The endpoint definitely did register as can be seen in the console:

{noformat}
[Mar 11 14:15:02] VERBOSE[15685] asterisk.c: Remote UNIX connection
[Mar 11 14:15:02] VERBOSE[494] asterisk.c: Remote UNIX connection disconnected
[Mar 11 14:15:02] VERBOSE[498] manager.c: Manager 'myasterisk' logged on from 127.0.0.1
[Mar 11 14:15:07] VERBOSE[538] res_pjsip_registrar.c: Added contact 'sip:example_ep@10.75.22.32:50328;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' to AOR 'example_ep' with expiration of 31536000 seconds
[Mar 11 14:15:07] VERBOSE[538] res_pjsip_registrar.c: Removed contact 'sip:example_ep@10.75.22.32:50252;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' from AOR 'example_ep' due to remove existing
[Mar 11 14:16:02] VERBOSE[498] manager.c: Manager 'myasterisk' logged off from 127.0.0.1
{noformat}

Which you can see happened within the connection to the manager.

Comments: By: Asterisk Team (asteriskteam) 2021-03-12 06:53:34.869-0600

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. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

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].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Joshua C. Colp (jcolp) 2021-03-12 08:08:48.632-0600

Are you going from Asterisk 13 to Asterisk 18 and noticing this change? I ask because I remembered this from UPGRADE.txt:

{noformat}
- The ContactStatus event will no longer be sent by PJSIP when a device
refreshes its registration.
{noformat}

In the case you've provided a Contact displaced another so it's not a refresh, but from the perspective of the contact status nothing would have changed by replacing the Contact. In previous versions this would still result in a ContactStatus being sent.
By: Brian J. Murrell (brian_j_murrell) 2021-03-12 13:15:53.876-0600

The endpoint status update in the successful case looks like:

{noformat}
[Mar 11 19:15:01] VERBOSE[30959] asterisk.c: Remote UNIX connection
[Mar 11 19:15:01] VERBOSE[1029] asterisk.c: Remote UNIX connection disconnected
[Mar 11 19:15:01] VERBOSE[1034] manager.c: Manager 'myasterisk' logged on from 127.0.0.1
[Mar 11 19:15:06] VERBOSE[960] res_pjsip_registrar.c: Added contact 'sip:example_ep@10.75.22.32:50806;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' to AOR 'example_ep' with expiration of 31536000 seconds
[Mar 11 19:15:06] VERBOSE[960] res_pjsip_registrar.c: Removed contact 'sip:example_ep@10.75.22.32:50788;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' from AOR 'example_ep' due to remove existing
[Mar 11 19:15:06] VERBOSE[961] res_pjsip/pjsip_options.c: Contact example_ep/sip:example_ep@10.75.22.32:50788;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1 has been deleted
[Mar 11 19:15:06] VERBOSE[1034] manager.c: Manager 'myasterisk' logged off from 127.0.0.1
{noformat}

Are you saying the difference is the:

{noformat}
[Mar 11 19:15:06] VERBOSE[961] res_pjsip/pjsip_options.c: Contact example_ep/sip:example_ep@10.75.22.32:50788;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1 has been deleted
{noformat}

If so, I'm not sure I understand the difference in those two cases. They are both cases of a contact that registers at some point for a very long time, and then comes back an re-registers. So why is one treated differently than the other?
By: Joshua C. Colp (jcolp) 2021-03-12 13:24:49.038-0600

I'd suggest attaching logs of non-working and working cases with complete debug level output including the AMI events instead of embedding the information as comments in here, it makes it hard to move around and see. The debug information also contains information about determining the status of things, including if they change or don't change.
By: Brian J. Murrell (brian_j_murrell) 2021-03-12 13:33:34.691-0600

I have added to {{logger.conf}}:

{noformat}
debug_ASTERISK-29344 => notice,warning,error,debug,verbose
{noformat}

but I'm not finding any info specific to having AMI events in that log.
By: Joshua C. Colp (jcolp) 2021-03-12 13:38:36.533-0600

At a debug level of 3 it should appear in the log. Otherwise "manager set debug on" can be done in the CLI, or debug can be enabled in manager.conf
By: Brian J. Murrell (brian_j_murrell) 2021-03-12 15:09:30.832-0600

I added:

{noformat}
debug_ASTERISK-29344 => notice,warning,error,debug(3)
{noformat}

But even after a while I only have ever gotten:

{noformat}
[Mar 12 15:09:54] Asterisk 18.2.2 built by mockbuild @ e9c968fd5e8c41ddbae5709f7edad128 on a x86_64 running Linux on 2021-03-07 22:00:27 UTC
{noformat}

I must not be doing it correctly.
By: Benjamin Keith Ford (bford) 2021-03-15 14:08:23.497-0500

Is the log file being generated? You can try rotating the logs as well to see if that starts outputting the information to the file. Make sure Asterisk is either restarted or you reload the logging configuration as well. You can also try starting Asterisk with a higher debug level ({{asterisk -cddddd}}) and see if that changes the results.
By: Brian J. Murrell (brian_j_murrell) 2021-03-15 14:16:20.757-0500

I am getting some output in the file with {{debug_ASTERISK-29344 => notice,warning,error,debug(3)}}, so that is good. It's unclear to me if that logger actually needs the {{notice,warning,error,}} in it, or if {{debug_ASTERISK-29344 => debug(3)}} should be all I need.
By: Benjamin Keith Ford (bford) 2021-03-15 14:41:28.678-0500

Those can be kept - it will help us get a better idea of what's going in. Once you've got the logs with debug enabled showing the event being dropped, can you attach that to the issue?
By: Brian J. Murrell (brian_j_murrell) 2021-03-15 16:05:25.323-0500

Are we sure:

{noformat}
debug_ASTERISK-29344 => notice,warning,error,debug(3)
{noformat}

in {{logger.conf}} is the correct syntax? With that set, /var/log/asterisk/debug_ASTERISK-29344 reports nothing at all, even from a working case of this issue (where the AMI reports the Contact registration as expected).
By: Benjamin Keith Ford (bford) 2021-03-16 11:34:59.772-0500

If you have the following in your logger.conf:
{{debug_ASTERISK-29344 => notice,warning,error,debug,verbose(3)}}
and you start Asterisk with:
{{asterisk -cddd}}
you will get the debug messages in the log file. This starts Asterisk with a debug level of 3, which can also be set if Asterisk is already running by using the CLI command {{core set debug #}}.
By: Brian J. Murrell (brian_j_murrell) 2021-03-16 13:08:46.201-0500

The logging is still not working:

{noformat}
server*CLI> core set debug 3
Core debug was OFF and is now 3.
-- Remote UNIX connection
-- Remote UNIX connection disconnected
== Manager 'myasterisk' logged on from 127.0.0.1
-- Added contact 'sip:example_ep@10.75.22.32:43338;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' to AOR 'example_ep' with expiration of 31536000 seconds
-- Removed contact 'sip:example_ep@10.75.22.32:43286;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1' from AOR 'example_ep' due to remove existing
== Contact example_ep/sip:example_ep@10.75.22.32:43286;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1 has been deleted
== Manager 'myasterisk' logged off from 127.0.0.1
server*CLI>
{noformat}

And here is the AMI conversation from the above:

{noformat}
Tue Mar 16 14:02:41 EDT 2021: Asterisk Call Manager/7.0.0
Tue Mar 16 14:02:41 EDT 2021: Response: Success
Tue Mar 16 14:02:41 EDT 2021: Message: Authentication accepted
Tue Mar 16 14:02:41 EDT 2021:
Tue Mar 16 14:02:41 EDT 2021: Event: FullyBooted
Tue Mar 16 14:02:41 EDT 2021: Privilege: system,all
Tue Mar 16 14:02:41 EDT 2021: Uptime: 15886
Tue Mar 16 14:02:41 EDT 2021: LastReload: 15886
Tue Mar 16 14:02:41 EDT 2021: Status: Fully Booted
Tue Mar 16 14:02:41 EDT 2021:
Tue Mar 16 14:02:41 EDT 2021: Event: SuccessfulAuth
Tue Mar 16 14:02:41 EDT 2021: Privilege: security,all
Tue Mar 16 14:02:41 EDT 2021: Timestamp: 1615917760.580834
Tue Mar 16 14:02:41 EDT 2021: SystemName: pbx.example.com
Tue Mar 16 14:02:41 EDT 2021: EventTV: 2021-03-16T14:02:40.580-0400
Tue Mar 16 14:02:41 EDT 2021: Severity: Informational
Tue Mar 16 14:02:41 EDT 2021: Service: AMI
Tue Mar 16 14:02:41 EDT 2021: EventVersion: 1
Tue Mar 16 14:02:41 EDT 2021: AccountID: myasterisk
Tue Mar 16 14:02:41 EDT 2021: SessionID: 0x7ff8580e8cc0
Tue Mar 16 14:02:41 EDT 2021: LocalAddress: IPV4/TCP/127.0.0.1/5038
Tue Mar 16 14:02:41 EDT 2021: RemoteAddress: IPV4/TCP/127.0.0.1/49020
Tue Mar 16 14:02:41 EDT 2021: UsingPassword: 0
Tue Mar 16 14:02:41 EDT 2021: SessionTV: 2021-03-16T14:02:40.580-0400
Tue Mar 16 14:02:41 EDT 2021:
Tue Mar 16 14:02:41 EDT 2021: Event: ChallengeSent
Tue Mar 16 14:02:41 EDT 2021: Privilege: security,all
Tue Mar 16 14:02:41 EDT 2021: Timestamp: 1615917761.683324
Tue Mar 16 14:02:41 EDT 2021: SystemName: pbx.example.com
Tue Mar 16 14:02:41 EDT 2021: EventTV: 2021-03-16T14:02:41.683-0400
Tue Mar 16 14:02:41 EDT 2021: Severity: Informational
Tue Mar 16 14:02:41 EDT 2021: Service: PJSIP
Tue Mar 16 14:02:41 EDT 2021: EventVersion: 1
Tue Mar 16 14:02:41 EDT 2021: AccountID: example_ep
Tue Mar 16 14:02:41 EDT 2021: SessionID: oWISESEXwJ
Tue Mar 16 14:02:41 EDT 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Tue Mar 16 14:02:41 EDT 2021: RemoteAddress: IPV4/TCP/10.75.22.32/43338
Tue Mar 16 14:02:41 EDT 2021: Challenge:
Tue Mar 16 14:02:41 EDT 2021:
Tue Mar 16 14:02:41 EDT 2021: Event: SuccessfulAuth
Tue Mar 16 14:02:41 EDT 2021: Privilege: security,all
Tue Mar 16 14:02:41 EDT 2021: Timestamp: 1615917761.699654
Tue Mar 16 14:02:41 EDT 2021: SystemName: pbx.example.com
Tue Mar 16 14:02:41 EDT 2021: EventTV: 2021-03-16T14:02:41.699-0400
Tue Mar 16 14:02:41 EDT 2021: Severity: Informational
Tue Mar 16 14:02:41 EDT 2021: Service: PJSIP
Tue Mar 16 14:02:41 EDT 2021: EventVersion: 1
Tue Mar 16 14:02:41 EDT 2021: AccountID: example_ep
Tue Mar 16 14:02:41 EDT 2021: SessionID: oWISESEXwJ
Tue Mar 16 14:02:41 EDT 2021: LocalAddress: IPV4/TCP/10.75.22.8/5060
Tue Mar 16 14:02:41 EDT 2021: RemoteAddress: IPV4/TCP/10.75.22.32/43338
Tue Mar 16 14:02:41 EDT 2021: UsingPassword: 1
Tue Mar 16 14:02:41 EDT 2021:
Tue Mar 16 14:02:41 EDT 2021: Event: ContactStatus
Tue Mar 16 14:02:41 EDT 2021: Privilege: system,all
Tue Mar 16 14:02:41 EDT 2021: Timestamp: 1615917761.701747
Tue Mar 16 14:02:41 EDT 2021: SystemName: pbx.example.com
Tue Mar 16 14:02:41 EDT 2021: URI: sip:example_ep@10.75.22.32:43338;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1
Tue Mar 16 14:02:41 EDT 2021: ContactStatus: NonQualified
Tue Mar 16 14:02:41 EDT 2021: AOR: example_ep
Tue Mar 16 14:02:41 EDT 2021: EndpointName: example_ep
{noformat}

and yet the {{/var/log/asterisk/debug_ASTERISK-29344}} has nothing after:

{noformat}
[Mar 16 13:51:30] NOTICE[15698] res_pjsip_session.c: anonymous: Call (UDP:193.46.255.62:1026) to extension '011972597147567' rejected because extension not found in context '[redacted]'.
{noformat}
By: Brian J. Murrell (brian_j_murrell) 2021-03-17 07:56:30.348-0500

Do I need to open a new ticket about logging not working correctly? Now that I look at the log, not a single message has DEBUG on it. All are WARNING, NOTICE, ERROR despite all of the above comments.
By: Benjamin Keith Ford (bford) 2021-03-17 10:10:51.863-0500

Logging is working, I set up a log file the other day with DEBUG output in it. There's probably just a step that's being missed. If you start Asterisk with {{-ddd}} or if you do {{core set debug 3}} on the CLI, do you see DEBUG statements in the CLI itself? If you don't, what does your logger.conf look like?
By: Brian J. Murrell (brian_j_murrell) 2021-03-17 10:24:20.684-0500

I think I pretty clearly described what I did in https://issues.asterisk.org/jira/browse/ASTERISK-29344?focusedCommentId=254183&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-254183 which includes issuing a {{core set debug 3}} which Asterisk reported {{Core debug was OFF and is now 3.}}.

I have not seen a single DEBUG message in the log configured as:

{noformat}
debug_ASTERISK-29344 => notice,warning,error,debug(3)
{noformat}

in {{logger.conf}}. Is that (in particular {{debug(3)}}) syntax actually correct or not?
By: Brian J. Murrell (brian_j_murrell) 2021-03-17 10:43:38.262-0500

I removed the {{(3)}} from the {{debug}} and now getting {{DEBUG}} messages.
By: Benjamin Keith Ford (bford) 2021-03-17 10:47:23.828-0500

You don't need the {{(3)}} after {{debug}}. If you copy and paste what I have in my above comment ({{notice,warning,error,debug,verbose(3)}}), the DEBUG messages should show up in the log.
By: Brian J. Murrell (brian_j_murrell) 2021-03-17 10:52:34.190-0500

Why is the {{(3)}} valid for {{verbose}} and not {{debug}}? That seems inconsistent and an avenue to frustration and confusion at best.
By: Benjamin Keith Ford (bford) 2021-03-17 11:33:57.878-0500

{{verbose}} is generally more chatty then {{debug}} and usually is enough to determine what's going on. Being able to specify a {{verbose}} level for logs without having to enable it and be spammed with messages in the CLI makes it a bit easier on us and users to provide additional information. I do agree though, the discrepancy is a bit confusing and is something I've brought up with the team.
By: Joshua C. Colp (jcolp) 2021-03-18 10:52:09.378-0500

Looking back at my notes I also asked about going from 13 to 18. This is currently marked as a regression, did this work with a previous version (which one) and now does not?
By: Brian J. Murrell (brian_j_murrell) 2021-03-23 06:29:03.275-0500

{quote}
This is currently marked as a regression, did this work with a previous version (which one) and now does not?
{quote}

Yes, this worked with 13.

I have logs for a working and non-working cases:

Working:

{noformat}
[Mar 23 04:15:03] DEBUG[13049] manager.c: Running action 'Login'
[Mar 23 04:15:03] DEBUG[13049] manager.c: Examining AMI event:
Event: SuccessfulAuth
Privilege: security,all
Timestamp: 1616487303.124256
SystemName: pbx.example.com
EventTV: 2021-03-23T04:15:03.124-0400
Severity: Informational
Service: AMI
EventVersion: 1
AccountID: [redacted]
SessionID: 0x7f02900d94d0
LocalAddress: IPV4/TCP/127.0.0.1/5038
RemoteAddress: IPV4/TCP/127.0.0.1/49360
UsingPassword: 0
SessionTV: 2021-03-23T04:15:03.124-0400

[Mar 23 04:15:09] DEBUG[28094] res_pjsip/pjsip_transport_events.c: Reliable transport 'tcps0x7f02b40c6828' state:CONNECTED
[Mar 23 04:15:09] DEBUG[28094] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=20 (rdata0x7f02b40c6b08)
[Mar 23 04:15:09] DEBUG[28094] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000044 to use for Request msg REGISTER/cseq=20 (rdata0x7f02b40c6b08)
[Mar 23 04:15:09] DEBUG[28092] threadpool.c: Increasing threadpool pjsip/pool's size by 5
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted1]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted2]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted3]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted4]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted5]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted6]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'example_ep' domain 'example.com'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_user.c: Identified by From username 'example_ep' domain 'example.com'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth 'example_ep'.
[Mar 23 04:15:09] DEBUG[13049] manager.c: Examining AMI event:
Event: ChallengeSent
Privilege: security,all
Timestamp: 1616487309.168980
SystemName: pbx.example.com
EventTV: 2021-03-23T04:15:09.168-0400
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: example_ep
SessionID: xSZo4AEZhF
LocalAddress: IPV4/TCP/10.75.22.8/5060
RemoteAddress: IPV4/TCP/10.75.22.32/48496
Challenge:

[Mar 23 04:15:09] DEBUG[28094] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=21 (rdata0x7f02b40c6b08)
[Mar 23 04:15:09] DEBUG[28094] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000044 to use for Request msg REGISTER/cseq=21 (rdata0x7f02b40c6b08)
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted1]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted2]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted3]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted4]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted5]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_ip.c: Source address 10.75.22.32:48496 does not match identify '[redacted6]'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'example_ep' domain 'example.com'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_endpoint_identifier_user.c: Identified by From username 'example_ep' domain 'example.com'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth 'example_ep'.
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_authenticator_digest.c: Calculated nonce 1616487309/99a0274a01e5ec217627e1f78520541c. Actual nonce is 1616487309/99a0274a01e5ec217627e1f78520541c
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_registrar.c: Matched id 'example_ep' to aor 'example_ep'
[Mar 23 04:15:09] DEBUG[13088] res_pjsip_registrar.c: Matched aor 'example_ep' by To username
[Mar 23 04:15:09] DEBUG[13088] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract uint from [48376] in [0, 4294967295] gives [48376](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract uint from [0] in [0, 86400] gives [0](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Mar 23 04:15:09] DEBUG[13088] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 23 04:15:09] DEBUG[13049] manager.c: Examining AMI event:
Event: SuccessfulAuth
Privilege: security,all
Timestamp: 1616487309.215436
SystemName: pbx.example.com
EventTV: 2021-03-23T04:15:09.215-0400
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: example_ep
SessionID: xSZo4AEZhF
LocalAddress: IPV4/TCP/10.75.22.8/5060
RemoteAddress: IPV4/TCP/10.75.22.32/48496
UsingPassword: 1

[Mar 23 04:15:09] DEBUG[28068] threadpool.c: Increasing threadpool sorcery/pool's size by 1
[Mar 23 04:15:09] DEBUG[13049] manager.c: Examining AMI event:
Event: ContactStatus
Privilege: system,all
Timestamp: 1616487309.219386
SystemName: pbx.example.com
URI: sip:example_ep@10.75.22.32:48496;transport=tcp;pn-type=firebase;app-id=[redacted];pn-tok=[redacted];pn-timeout=0;pn-silent=1
ContactStatus: NonQualified
AOR: example_ep
EndpointName: example_ep
RoundtripUsec: 0

{noformat}

Not working:
{noformat}
[Mar 23 06:15:02] DEBUG[22797] manager.c: Running action 'Login'
[Mar 23 06:15:02] DEBUG[22797] manager.c: Examining AMI event:
Event: SuccessfulAuth
Privilege: security,all
Timestamp: 1616494502.521180
SystemName: pbx.example.com
EventTV: 2021-03-23T06:15:02.521-0400
Severity: Informational
Service: AMI
EventVersion: 1
AccountID: [redacted]
SessionID: 0x7f02900d94d0
LocalAddress: IPV4/TCP/127.0.0.1/5038
RemoteAddress: IPV4/TCP/127.0.0.1/53090
UsingPassword: 0
SessionTV: 2021-03-23T06:15:02.521-0400

{noformat}

and that's it. Nothing more. The AMI conversation for the above not working though is:

{noformat}
Tue Mar 23 06:15:01 EDT 2021
Tue Mar 23 06:15:02 EDT 2021: Asterisk Call Manager/7.0.0
Tue Mar 23 06:15:02 EDT 2021: Response: Success
Tue Mar 23 06:15:02 EDT 2021: Message: Authentication accepted
Tue Mar 23 06:15:02 EDT 2021:
Tue Mar 23 06:15:02 EDT 2021: Event: FullyBooted
Tue Mar 23 06:15:02 EDT 2021: Privilege: system,all
Tue Mar 23 06:15:02 EDT 2021: Uptime: 507872
Tue Mar 23 06:15:02 EDT 2021: LastReload: 507872
Tue Mar 23 06:15:02 EDT 2021: Status: Fully Booted
Tue Mar 23 06:15:02 EDT 2021:
Tue Mar 23 06:15:02 EDT 2021: Event: SuccessfulAuth
Tue Mar 23 06:15:02 EDT 2021: Privilege: security,all
Tue Mar 23 06:15:02 EDT 2021: Timestamp: 1616494502.521180
Tue Mar 23 06:15:02 EDT 2021: SystemName: pbx.example.com
Tue Mar 23 06:15:02 EDT 2021: EventTV: 2021-03-23T06:15:02.521-0400
Tue Mar 23 06:15:02 EDT 2021: Severity: Informational
Tue Mar 23 06:15:02 EDT 2021: Service: AMI
Tue Mar 23 06:15:02 EDT 2021: EventVersion: 1
Tue Mar 23 06:15:02 EDT 2021: AccountID: myasterisk
Tue Mar 23 06:15:02 EDT 2021: SessionID: 0x7f02900d94d0
Tue Mar 23 06:15:02 EDT 2021: LocalAddress: IPV4/TCP/127.0.0.1/5038
Tue Mar 23 06:15:02 EDT 2021: RemoteAddress: IPV4/TCP/127.0.0.1/53090
Tue Mar 23 06:15:02 EDT 2021: UsingPassword: 0
Tue Mar 23 06:15:02 EDT 2021: SessionTV: 2021-03-23T06:15:02.521-0400
{noformat}
By: Joshua C. Colp (jcolp) 2021-03-23 06:38:18.908-0500

I'm not sure what your not working case is supposed to show.

In the working case you connected via AMI, after which a SIP client connected using TCP to Asterisk and then did a REGISTER. This caused the ContactStatus event to get sent.

In the not working case you connected via AMI and then nothing. No SIP client connected using TCP, no REGISTER came in, nothing. I wouldn't expect a ContactStatus in this case - as nothing changed.
By: George Joseph (gjoseph) 2021-03-23 06:47:50.365-0500

I'm also confused by the lack of debug output. With debug level = 3 there should be tons of debug messages showing up.

By: Brian J. Murrell (brian_j_murrell) 2021-03-23 07:54:29.952-0500

Hrm. Yeah. Now that I look, that not-working does not represent the case I am reporting here.

Looks like two things are going on. One on Asterisk and one on the client. To get more info on the Asterisk one though, I need to enable pjsip logging for the host to capture the SIP conversation.
By: Asterisk Team (asteriskteam) 2021-04-06 12:00:00.939-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines