[asterisk-bugs] [JIRA] (ASTERISK-29344) AMI Contact events getting dropped

Wed Mar 17 11:34:15 CDT 2021

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29344?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=254205#comment-254205 ] 

Benjamin Keith Ford commented on ASTERISK-29344:
------------------------------------------------

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

> AMI Contact events getting dropped
> ----------------------------------
>
>                 Key: ASTERISK-29344
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29344
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: General
>    Affects Versions: 18.2.2
>            Reporter: Brian J. Murrell
>            Assignee: Unassigned
>
> 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 at 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 at 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 at 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.

--
This message was sent by Atlassian JIRA
(v6.2#6252)