[asterisk-bugs] [JIRA] (ASTERISK-29344) ami: Contact events getting dropped
Brian J. Murrell (JIRA)
noreply at issues.asterisk.org
Tue Mar 23 06:29:15 CDT 2021
[ https://issues.asterisk.org/jira/browse/ASTERISK-29344?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=254289#comment-254289 ]
Brian J. Murrell commented on ASTERISK-29344:
---------------------------------------------
{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 at 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.interlinx.bc.ca
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}
> 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: Core/ManagerInterface, Resources/res_pjsip_registrar
> Affects Versions: 18.2.2
> Reporter: Brian J. Murrell
> Assignee: Brian J. Murrell
>
> 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)
More information about the asterisk-bugs
mailing list