ASTERISK-28705: chan_sip: Phones loose abiltiy to work, core restarting asterisk fixes issue

[Home]

Summary: ASTERISK-28705: chan_sip: Phones loose abiltiy to work, core restarting asterisk fixes issue

Reporter: Dan (dwsiemens) Labels:

Date Opened: 2020-01-20 11:52:19.000-0600 Date Closed:

Priority: Major Regression?

Status: Open/New Components: Channels/chan_sip/General

Versions: 16.7.0 Frequency of
Occurrence Occasional

Related
Issues:

Environment: I have a Redhat HA cluster running with 2 Rhel 7 nodes with asterisk 16.7.0 Attachments:

Description: Incoming calls on Chan sip still come into the sytem. Calls in flight stay running.

Endpoints get a "x" on them being ploycom phone model vvx310, 311, soundpoint 430, 450's and zoipe soft phones.

THere are no messages about phones loosing registration.

A core restart now on asterisk fixes the issue.

I think the problem started around asterisk 16.4.0

Comments: By: Asterisk Team (asteriskteam) 2020-01-20 11:52:20.441-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.

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.
By: Dan (dwsiemens) 2020-01-20 11:54:21.283-0600

{noformat}
2020-01-20T10:48:45.186290-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77846][C-00001a43]: pbx.c:2945 in pbx_extension_helper: Executing [s@GreatDane-Menu-Root:4] NoOp("Local/39028@stations-0000034d;2", "GreatDane is OPEN") in new stack
2020-01-20T10:48:45.186299-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77846][C-00001a43]: pbx.c:2945 in pbx_extension_helper: Executing [s@GreatDane-Menu-Root:5] Goto("Local/39028@stations-0000034d;2", "GreatDane-Menu-Trunk-Business-Hours,s,1") in new stack
2020-01-20T10:48:45.186307-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77846][C-00001a43]: pbx_builtins.c:867 in pbx_builtin_goto: Goto (GreatDane-Menu-Trunk-Business-Hours,s,1)
2020-01-20T10:48:45.186314-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77846][C-00001a43]: pbx.c:2945 in pbx_extension_helper: Executing [s@GreatDane-Menu-Trunk-Business-Hours:1] BackGround("Local/39028@stations-0000034d;2", "greatdane/business-hour-greeting") in new stack
2020-01-20T10:48:45.186819-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mExecuting [s@GreatDane-Menu-Root:2] #033[1;36mGotoIfTime#033[0m("#033[1;35mLocal/39028@stations-0000034d;2#033[0m", "#033[1;35m08:00-19:00,mon-fri,*,*?open#033[0m") in new stack
2020-01-20T10:48:45.187088-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mGoto (GreatDane-Menu-Root,s,4)
2020-01-20T10:48:45.187336-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mExecuting [s@GreatDane-Menu-Root:4] #033[1;36mNoOp#033[0m("#033[1;35mLocal/39028@stations-0000034d;2#033[0m", "#033[1;35mGreatDane is OPEN#033[0m") in new stack
2020-01-20T10:48:45.188263-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77846][C-00001a43]: file.c:1295 in ast_streamfile: <Local/39028@stations-0000034d;2> Playing 'greatdane/business-hour-greeting.ulaw' (language 'en')
2020-01-20T10:48:45.187535-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mExecuting [s@GreatDane-Menu-Root:5] #033[1;36mGoto#033[0m("#033[1;35mLocal/39028@stations-0000034d;2#033[0m", "#033[1;35mGreatDane-Menu-Trunk-Business-Hours,s,1#033[0m") in new stack
2020-01-20T10:48:45.187730-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mGoto (GreatDane-Menu-Trunk-Business-Hours,s,1)
2020-01-20T10:48:45.187926-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0mExecuting [s@GreatDane-Menu-Trunk-Business-Hours:1] #033[1;36mBackGround#033[0m("#033[1;35mLocal/39028@stations-0000034d;2#033[0m", "#033[1;35mgreatdane/business-hour-greeting#033[0m") in new stack
2020-01-20T10:48:45.188707-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0m<Local/39028@stations-0000034d;2> Playing 'greatdane/business-hour-greeting.ulaw' (language 'en')
2020-01-20T10:48:45.899886-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:45.899] #033[1;32mDTMF#033[0m[77755][C-00001a58]: #033[1;37mchannel.c#033[0m:#033[1;37m3987#033[0m #033[1;37m__ast_read#033[0m: DTMF begin '#' received on SIP/opmgw23-00002e42
2020-01-20T10:48:45.900185-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:45.899] #033[1;32mDTMF#033[0m[77755][C-00001a58]: #033[1;37mchannel.c#033[0m:#033[1;37m3991#033[0m #033[1;37m__ast_read#033[0m: DTMF begin ignored '#' on SIP/opmgw23-00002e42
2020-01-20T10:48:45.937279-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:45.936] #033[1;32mDTMF#033[0m[77755][C-00001a58]: #033[1;37mchannel.c#033[0m:#033[1;37m3873#033[0m #033[1;37m__ast_read#033[0m: DTMF end '#' received on SIP/opmgw23-00002e42, duration 50 ms
2020-01-20T10:48:45.937521-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:45.936] #033[1;32mDTMF#033[0m[77755][C-00001a58]: #033[1;37mchannel.c#033[0m:#033[1;37m3962#033[0m #033[1;37m__ast_read#033[0m: DTMF end passthrough '#' on SIP/opmgw23-00002e42
2020-01-20T10:48:45.938716-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[77755][C-00001a58]: res_agi.c:2580 in handle_streamfile: <SIP/opmgw23-00002e42> Playing 'en/authsystem/please-enter-card.gsm' (escape_digits=#*0123456789) (sample_offset 0) (language 'en')
2020-01-20T10:48:45.939198-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m -- #033[0m<SIP/opmgw23-00002e42> Playing 'en/authsystem/please-enter-card.gsm' (escape_digits=#*0123456789) (sample_offset 0) (language 'en')
2020-01-20T10:48:46.337811-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:46.337] #033[1;32mDTMF#033[0m[77486][C-00001a41]: #033[1;37mchannel.c#033[0m:#033[1;37m3987#033[0m #033[1;37m__ast_read#033[0m: DTMF begin '#' received on SIP/Sarah-Martin-00002e1d
2020-01-20T10:48:46.338103-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:46.337] #033[1;32mDTMF#033[0m[77486][C-00001a41]: #033[1;37mchannel.c#033[0m:#033[1;37m3998#033[0m #033[1;37m__ast_read#033[0m: DTMF begin passthrough '#' on SIP/Sarah-Martin-00002e1d
2020-01-20T10:48:46.397846-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:48:46.397] #033[1;32mDTMF#033[0m[77486][C-00001a41]: #033[1;37mchannel...skipping...
2020-01-20T10:52:53.711731-06:00 vmctel22.multiservice.com sendmail[78724]: 00KGqr1U078724: from=asterisk, size=72250, class=0, nrcpts=1, msgid=<Asterisk-1-1620423055-32871-111592@vmctel22.multiservice.com>, relay=asterisk@localhost
2020-01-20T10:52:53.775537-06:00 vmctel22.multiservice.com sendmail[78725]: 00KGqrL0078725: from=<asterisk@vmctel22.multiservice.com>, size=72391, class=0, nrcpts=1, msgid=<Asterisk-1-1620423055-32871-111592@vmctel22.multiservice.com>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1]
2020-01-20T10:52:53.783655-06:00 vmctel22.multiservice.com sendmail[78724]: 00KGqr1U078724: to="Jodi Hall" <jhall@multiservice.com>, ctladdr=asterisk (209/206), delay=00:00:00, xdelay=00:00:00, mailer=relay, pri=102250, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (00KGqrL0078725 Message accepted for delivery)
2020-01-20T10:52:54.365865-06:00 vmctel22.multiservice.com sendmail[78727]: 00KGqrL0078725: to=<jhall@multiservice.com>, ctladdr=<asterisk@vmctel22.multiservice.com> (209/206), delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=192391, relay=mail-dlp.multiservice.com. [172.24.112.131], dsn=2.0.0, stat=Sent (00KGqrkG011784 Message accepted for delivery)
2020-01-20T10:52:54.493331-06:00 vmctel22.multiservice.com asterisk[111592]: NOTICE[111641]: chan_sip.c:28942 in handle_request_register: Registration from '<sip:450-Test@siptel02.multiservice.com>' failed for '10.119.221.2:5060' - Wrong password
2020-01-20T10:52:54.493784-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:52:54.493] #033[1;33mNOTICE#033[0m[111641]: #033[1;37mchan_sip.c#033[0m:#033[1;37m28942#033[0m #033[1;37mhandle_request_register#033[0m: Registration from '<sip:450-Test@siptel02.multiservice.com>' failed for '10.119.221.2:5060' - Wrong password
2020-01-20T10:52:54.545986-06:00 vmctel22.multiservice.com asterisk[111592]: NOTICE[111641]: chan_sip.c:28942 in handle_request_register: Registration from '<sip:Bob-Featherston@multiservice.com>' failed for '10.119.221.44:5060' - Wrong password
2020-01-20T10:52:54.546354-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:52:54.545] #033[1;33mNOTICE#033[0m[111641]: #033[1;37mchan_sip.c#033[0m:#033[1;37m28942#033[0m #033[1;37mhandle_request_register#033[0m: Registration from '<sip:Bob-Featherston@multiservice.com>' failed for '10.119.221.44:5060' - Wrong password
2020-01-20T10:52:54.833750-06:00 vmctel22.multiservice.com asterisk[111592]: NOTICE[111641]: chan_sip.c:28942 in handle_request_register: Registration from '<sip:450-Test@siptel02.multiservice.com>' failed for '10.119.221.29:5060' - Wrong password
2020-01-20T10:52:54.834190-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:52:54.833] #033[1;33mNOTICE#033[0m[111641]: #033[1;37mchan_sip.c#033[0m:#033[1;37m28942#033[0m #033[1;37mhandle_request_register#033[0m: Registration from '<sip:450-Test@siptel02.multiservice.com>' failed for '10.119.221.29:5060' - Wrong password
2020-01-20T10:52:56.216590-06:00 vmctel22.multiservice.com asterisk[7330]: NOTICE[10394]: chan_sip.c:28942 in handle_request_register: Registration from '<sip:lwatkins@172.25.220.18;transport=TCP>' failed for '10.119.100.51:60833' - Wrong password
2020-01-20T10:52:56.703673-06:00 vmctel22.multiservice.com asterisk[111592]: NOTICE[111641]: chan_sip.c:28942 in handle_request_register: Registration from '<sip:Jessica-Coogle@multiservice.com>' failed for '10.119.221.13:5060' - Wrong password
2020-01-20T10:52:56.704388-06:00 vmctel22.multiservice.com asterisk[111592]: [2020-01-20 10:52:56.703] #033[1;33mNOTICE#033[0m[111641]: #033[1;37mchan_sip.c#033[0m:#033[1;37m28942#033[0m #033[1;37mhandle_request_register#033[0m: Registration from '<sip:Jessica-Coogle@multiservice.com>' failed for '10.119.221.13:5060' - Wrong password
2020-01-20T10:52:58.315150-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[111641][C-00001a8c]: netsock2.c:639 in ast_set_qos: Using SIP RTP TOS bits 184
2020-01-20T10:52:58.315180-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[111641][C-00001a8c]: netsock2.c:661 in ast_set_qos: Using SIP RTP CoS mark 5
2020-01-20T10:52:58.315617-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m == #033[0mUsing SIP RTP TOS bits 184
2020-01-20T10:52:58.315891-06:00 vmctel22.multiservice.com asterisk[111592]: #033[1;30m == #033[0mUsing SIP RTP CoS mark 5
2020-01-20T10:52:58.316707-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[111641][C-00001a8c]: res_rtp_asterisk.c:8052 in ast_rtp_remote_address_set: 0x3cf5970 -- Strict RTP learning after remote address set to: 10.123.240.178:36740
2020-01-20T10:52:58.317843-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[78729][C-00001a8c]: pbx.c:2945 in pbx_extension_helper: Executing [9133483901@gateways-inbound:1] DumpChan("SIP/ec2-tel36-00002ea1", "3") in new stack
2020-01-20T10:52:58.317868-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[78729][C-00001a8c]: app_dumpchan.c:191 in dumpchan_exec: #012Dumping Info For Channel: SIP/ec2-tel36-00002ea1:#012================================================================================#012Info:#012Name= SIP/ec2-tel36-00002ea1#012Type= SIP#012UniqueID= 1579539178.127703#012LinkedID= 1579539178.127703#012CallerIDNum= 6302300983#012CallerIDName= A S TRANS#012ConnectedLineIDNum= (N/A)#012ConnectedLineIDName=(N/A)#012DNIDDigits= 9133483901#012RDNIS= (N/A)#012Parkinglot= default#012Language= en#012State= Ring (4)#012Rings= 0#012NativeFormat= (g729)#012WriteFormat= g729#012ReadFormat= g729#012RawWriteFormat= g729#012RawReadFormat= g729#012WriteTranscode= No #012ReadTranscode= No #0121stFileDescriptor= 99#012Framesin= 0 #012Framesout= 0 #012TimetoHangup= 0#012ElapsedTime= 0h0m0s#012BridgeID= (Not bridged)#012Context= gateways-inbound#012Extension= 9133483901#012Priority= 1#012CallGroup= #012PickupGroup= #012Application= DumpChan#012Data= 3#012Blocking_in= (Not Blocking)#012#012Variables:#012SIPCALLID=57040245411a098e0108ea380f48f6cb@10.123.240.178:5060#012SIPDOMAIN=siptel02.multiservice.com#012SIPURI=sip:6302300983@10.123.240.178:5060#012================================================================================
2020-01-20T10:52:58.317949-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[78729][C-00001a8c]: pbx.c:2945 in pbx_extension_helper: Executing [9133483901@gateways-inbound:2] GotoIf("SIP/ec2-tel36-00002ea1", "0?blacklisted") in new stack
2020-01-20T10:52:58.317962-06:00 vmctel22.multiservice.com asterisk[111592]: VERBOSE[78729][C-00001a8c]: pbx.c:2945 in pbx_extension_helper: Executing [9133483901...skipping...
2020-01-20T11:00:04.113150-06:00 vmctel22.multiservice.com asterisk[111592]: ERROR[111707]:
(This is me shutting it down) manager.c:6552 in process_message: Unable to process manager action 'SIPShowPeer'. Asterisk is shutting down.
{noformat}
By: Joshua C. Colp (jcolp) 2020-01-20 11:55:14.457-0600

Have you looked to see if REGISTER requests are still coming into chan_sip? What does "sip show peer" output for them?

I should also add that chan_sip is community supported, so if a problem does exist there is no timeframe on when it will get looked into or even if it will.
By: Dan (dwsiemens) 2020-01-20 11:55:41.754-0600

my debug log has minimal info

{noformat}
[2020-01-20 09:19:39.977] DEBUG[52227][C-0000174b] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/41001/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 09:20:34.416] DEBUG[52626][C-00001757] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/stations/32645/Urgent' has no messages and therefore no index was retrieved.
[2020-01-20 09:26:02.483] DEBUG[53556][C-00001775] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/41001/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 09:27:48.447] DEBUG[53877][C-00001783] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/41001/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 09:33:55.824] DEBUG[54054][C-0000177a] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/stations/32871/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 09:34:20.915] DEBUG[55250][C-000017bd] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/stations/32871/Urgent' has no messages and therefore no index was retrieved.
[2020-01-20 09:43:03.511] DEBUG[56972][C-000017f5] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/33066/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 09:57:17.254] DEBUG[60272][C-0000186d] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/41001/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 10:14:52.010] DEBUG[63470][C-00001905] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/32812/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 10:43:53.096] DEBUG[67144][C-0000199f] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/32809/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 10:44:56.449] DEBUG[76858][C-00001a24] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/mailboxes/32809/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 10:48:44.283] DEBUG[77656][C-00001a4d] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/stations/32834/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 10:52:53.636] DEBUG[78530][C-00001a7c] app_voicemail.c: Directory '/var/spool/asterisk/voicemail/stations/32871/INBOX' has no messages and therefore no index was retrieved.
[2020-01-20 11:00:20.315] Asterisk 16.7.0 built by root @ opbld25.xxxxxx on a x86_64 running Linux on 2020-01-06 20:51:52 UTC
{noformat}
By: Dan (dwsiemens) 2020-01-20 11:57:09.021-0600

In past events I have

The peers still showed up. Its a bit tough as there are around 300 phones and so you its a bit tough to tell

By: Joshua C. Colp (jcolp) 2020-01-20 11:59:06.078-0600

Are you doing many reloads?
By: Dan (dwsiemens) 2020-01-20 12:02:18.983-0600

dialplan reloads several times a day for sure. M to friday. none on the weekends.

By: Dan (dwsiemens) 2020-01-20 20:34:45.288-0600

Happened when I was out of the office but I did have some debug logging on so a lot of data.

Here are a few different times in the logs

{noformat}
[2020-01-20 14:16:01.410] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: Local/0@stations-000000b4;2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: stations
Exten: 0
Priority: 1
Uniqueid: 1579551361.28095
Linkedid: 1579551256.27871
Variable: BRIDGEPEER
Value: Local/39200@pilots-000000b5;1

[2020-01-20 14:16:01.411] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Creating topic. name: channel:1579551361.28099, detail:
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Topic 'channel:1579551361.28099': 0x3007a30 created
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Creating topic. name: cache:31234/channel:1579551361.28099, detail:
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Topic 'cache:31234/channel:1579551361.28099': 0x12ef040 created
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Destroying topic. name: cache:31234/channel:1579551361.28099, detail:
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Topic 'cache:31234/channel:1579551361.28099': 0x12ef040 destroyed
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579551361.28099, detail:
[2020-01-20 14:16:01.411] DEBUG[80279] stasis.c: Topic 'channel:1579551361.28099': 0x3007a30 destroyed
[2020-01-20 14:16:01.411] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 14:16:01.411] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('CHAN_START', {ts '2020-01-20 14:16:01.403133'}, '', '', '', '', '', '', '39200', 'pilots', 'Local/39200@pilots-000000b5;1', '', '', 3, '', '', '1579551361.28096', '1579551256.27871', '', '')]
[2020-01-20 14:16:01.411] DEBUG[6983][C-0000066a] audiohook.c: Read factory 0x7fb53802b1a8 was pretty quick last time, waiting for them.
[2020-01-20 14:16:01.412] DEBUG[6990][C-0000066d] audiohook.c: Read factory 0x7fb5540b3928 and write factory 0x7fb5540b4368 both fail to provide 160 samples
[2020-01-20 14:16:01.412] DEBUG[6982][C-0000066d] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:16:01.412] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:16:01.412] DEBUG[80302] chan_sip.c: Stopping retransmission on '5ec59b1607424bc73943fd64417524d9@172.25.220.18:5060' of Request 102: Match Found
[2020-01-20 14:16:01.412] DEBUG[80302] chan_sip.c: Destroying SIP dialog 5ec59b1607424bc73943fd64417524d9@172.25.220.18:5060
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_basic.c: About to enter state Calling Target for attended transfer 0x7fb5600dee60
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge.c: Moving 0x7fb55c08a480(SIP/Sarah-Martin-00000ba1) into bridge ab550e1d-5464-463e-801e-a942b084a83d
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_channel.c: Bridge 8668b470-04cc-4b6b-b403-68e8663caedf: pulling 0x7fb55c08a480(SIP/Sarah-Martin-00000ba1)
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_channel.c: Bridge 8668b470-04cc-4b6b-b403-68e8663caedf: 0x7fb55c08a480(SIP/Sarah-Martin-00000ba1) is leaving simple_bridge technology
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_channel.c: Channel SIP/Sarah-Martin-00000ba1 will survive this bridge; clearing outgoing (dialed) flag
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_channel.c: Bridge ab550e1d-5464-463e-801e-a942b084a83d: pushing 0x7fb55c08a480(SIP/Sarah-Martin-00000ba1)
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_roles.c: Set role 'transferer'
[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] bridge_native_rtp.c: Bridge 'ab550e1d-5464-463e-801e-a942b084a83d'. Checking compatability for channels 'Local/0@stations-000000b4;1' and 'SIP/Sarah-Martin-00000ba1'
...skipping...
[2020-01-20 14:16:01.412] DEBUG[80357] manager.c: Examining AMI event:
Event: BridgeLeave
Privilege: call,all
BridgeUniqueid: 8668b470-04cc-4b6b-b403-68e8663caedf
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 1
BridgeVideoSourceMode: none
Channel: SIP/Sarah-Martin-00000ba1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: 5099616186
ConnectedLineName: MSfuel: fuel: RED CARPET MOTO
Language: en
AccountCode:
Context: stations
Exten: 31033
Priority: 1
Uniqueid: 1579551286.27935
Linkedid: 1579551256.27871

[2020-01-20 14:16:01.412] DEBUG[7167][C-00000666] channel.c: Channel SIP/Sarah-Martin-00000ba1 setting read format path: ulaw -> ulaw
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] channel.c: Channel Local/0@stations-000000b4;1 setting write format path: ulaw -> ulaw
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] channel.c: Channel Local/0@stations-000000b4;1 setting read format path: ulaw -> ulaw
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] channel.c: Channel SIP/Sarah-Martin-00000ba1 setting write format path: ulaw -> ulaw
[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: BridgeEnter
Privilege: call,all
BridgeUniqueid: ab550e1d-5464-463e-801e-a942b084a83d
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 2
BridgeVideoSourceMode: none
Channel: SIP/Sarah-Martin-00000ba1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: 5099616186
ConnectedLineName: MSfuel: fuel: RED CARPET MOTO
Language: en
AccountCode:
Context: stations
Exten: 31033
Priority: 1
Uniqueid: 1579551286.27935
Linkedid: 1579551256.27871

[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge_native_rtp.c: Bridge '8668b470-04cc-4b6b-b403-68e8663caedf' can not use native RTP bridge as two channels are required
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge.c: Bridge technology softmix does not have any capabilities we want.
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge.c: Chose bridge technology simple_bridge
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge.c: Bridge 8668b470-04cc-4b6b-b403-68e8663caedf is already using the new technology.
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge_basic.c: Received stimulus Transfer Target Answer on attended transfer 0x7fb5600dee60
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge_basic.c: Told to enter state Consulting exit on attended transfer 0x7fb5600dee60
[2020-01-20 14:16:01.413] DEBUG[7167][C-00000666] bridge_basic.c: About to enter state Consulting for attended transfer 0x7fb5600dee60
[2020-01-20 14:16:01.413] DEBUG[80278] cdr.c: Finalized CDR for SIP/ec2-tel36-00000b99 - start 1579551256.467809 answer 1579551256.488583 end 1579551296.096745 dispo ANSWERED
[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: Local/0@stations-000000b4;1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: 32902
ConnectedLineName: Sarah Martin
Language: en
AccountCode:
Context: stations
Exten: 0
Priority: 1
Uniqueid: 1579551361.28093
Linkedid: 1579551256.27871
Variable: BRIDGEPEER
Value: SIP/Sarah-Martin-00000ba1

[2020-01-20 14:16:01.413] DEBUG[80278] cdr.c: Finalized CDR for Local/0@stations-000000b4;1 - start 1579551361.401751 answer 1579551361.407260 end 1579551361.407284 dispo ANSWERED
[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: Local/0@stations-000000b4;1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: <unknown>
CallerIDName: <unknown>
ConnectedLineNum: 32902
ConnectedLineName: Sarah Martin
Language: en
AccountCode:
Context: stations
Exten: 0
Priority: 1
Uniqueid: 1579551361.28093
Linkedid: 1579551256.27871
Variable: BRIDGEPVTCALLID
Value: 6b2474343d0d05814002c44154a3075a@172.25.220.18:5060

[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/Sarah-Martin-00000ba1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: 5099616186
ConnectedLineName: MSfuel: fuel: RED CARPET MOTO
Language: en
AccountCode:
Context: stations
Exten: 31033
Priority: 1
Uniqueid: 1579551286.27935
Linkedid: 1579551256.27871
Variable: BRIDGEPEER
Value: Local/0@stations-000000b4;1

[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/Sarah-Martin-00000ba1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: 5099616186
ConnectedLineName: MSfuel: fuel: RED CARPET MOTO
Language: en
AccountCode:
Context: stations
Exten: 31033
Priority: 1
Uniqueid: 1579551286.27935
Linkedid: 1579551256.27871
Variable: BRIDGEPVTCALLID
Value:

[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: NewConnectedLine
Privilege: call,all
Channel: SIP/Sarah-Martin-00000ba1
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: stations
Exten: 31033
Priority: 1
Uniqueid: 1579551286.27935
Linkedid: 1579551256.27871

[2020-01-20 14:16:01.413] DEBUG[7166][C-00000666] pbx.c: Launching 'Wait'
[2020-01-20 14:16:01.413] DEBUG[80357] manager.c: Examining AMI event:
Event: Newexten
Privilege: dialplan,all
Channel: Local/39200@pilots-000000b5;2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 32902
CallerIDName: Sarah Martin
ConnectedLineNum: 0
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: queues
Exten: 31299
Priority: 3
Uniqueid: 1579551361.28097
Linkedid: 1579551256.27871
Extension: 31299
Application: Wait
AppData: 1

Now close to 16:25 time Logging lots more per second but they are all audio events. These are very common messages in the forms to see but that suggest it was doing more work around audio transcoding at the time prior to the event.

them.
[2020-01-20 14:25:59.393] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.394] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.395] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.396] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.397] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.399] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:25:59.400] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.401] DEBUG[9097][C-000006bf] audiohook.c: Failed to get 160 samples from write factory 0x7fb53400d9c8
[2020-01-20 14:25:59.401] DEBUG[9097][C-000006bf] audiohook.c: Read factory 0x7fb53400cf88 and write factory 0x7fb53400d9c8 both fail to provide 160 samples
[2020-01-20 14:25:59.402] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.403] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.404] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.405] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.409] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.411] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.412] DEBUG[7586][C-00000669] audiohook.c: Read factory 0x7fb54006d568 and write factory 0x7fb54006dfa8 both fail to provide 160 samples
[2020-01-20 14:25:59.412] DEBUG[7534][C-00000669] audiohook.c: Read factory 0x7fb54008f2d8 and write factory 0x7fb54008fd18 both fail to provide 160 samples
[2020-01-20 14:25:59.412] DEBUG[7586][C-00000669] audiohook.c: Write factory 0x7fb54006dfa8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.412] DEBUG[7534][C-00000669] audiohook.c: Write factory 0x7fb54008fd18 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.414] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.415] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.416] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.418] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.419] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:25:59.420] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.421] DEBUG[9097][C-000006bf] audiohook.c: Failed to get 160 samples from write factory 0x7fb53400d9c8
[2020-01-20 14:25:59.421] DEBUG[9097][C-000006bf] audiohook.c: Read factory 0x7fb53400cf88 and write factory 0x7fb53400d9c8 both fail to provide 160 samples
[2020-01-20 14:25:59.422] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.423] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.424] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.424] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.429] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.431] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.432] DEBUG[7534][C-00000669] audiohook.c: Read factory 0x7fb54008f2d8 and write factory 0x7fb54008fd18 both fail to provide 160 samples
[2020-01-20 14:25:59.432] DEBUG[7586][C-00000669] audiohook.c: Read factory 0x7fb54006d568 and write factory 0x7fb54006dfa8 both fail to provide 160 samples
[2020-01-20 14:25:59.432] DEBUG[7586][C-00000669] audiohook.c: Write factory 0x7fb54006dfa8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.432] DEBUG[7534][C-00000669] audiohook.c: Write factory 0x7fb54008fd18 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.434] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.435] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.436] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.437] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.438] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.439] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:25:59.440] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.441] DEBUG[9097][C-000006bf] audiohook.c: Failed to get 160 samples from write factory 0x7fb53400d9c8
[2020-01-20 14:25:59.441] DEBUG[9097][C-000006bf] audiohook.c: Read factory 0x7fb53400cf88 and write factory 0x7fb53400d9c8 both fail to provide 160 samples
[2020-01-20 14:25:59.442] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.444] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.444] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.450] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.452] DEBUG[7534][C-00000669] audiohook.c: Read factory 0x7fb54008f2d8 and write factory 0x7fb54008fd18 both fail to provide 160 samples
[2020-01-20 14:25:59.452] DEBUG[7586][C-00000669] audiohook.c: Read factory 0x7fb54006d568 and write factory 0x7fb54006dfa8 both fail to provide 160 samples
[2020-01-20 14:25:59.452] DEBUG[7534][C-00000669] audiohook.c: Write factory 0x7fb54008fd18 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.452] DEBUG[7586][C-00000669] audiohook.c: Write factory 0x7fb54006dfa8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.453] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.454] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.455] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.456] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.457] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.459] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:25:59.460] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.461] DEBUG[80302] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.119.101.23:5060
[2020-01-20 14:25:59.461] DEBUG[9097][C-000006bf] audiohook.c: Failed to get 160 samples from write factory 0x7fb53400d9c8
[2020-01-20 14:25:59.461] DEBUG[9097][C-000006bf] audiohook.c: Read factory 0x7fb53400cf88 and write factory 0x7fb53400d9c8 both fail to provide 160 samples
[2020-01-20 14:25:59.461] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.462] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.464] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.465] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.466] DEBUG[80302] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.119.100.12:5060
[2020-01-20 14:25:59.472] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.472] DEBUG[7534][C-00000669] audiohook.c: Read factory 0x7fb54008f2d8 and write factory 0x7fb54008fd18 both fail to provide 160 samples
[2020-01-20 14:25:59.472] DEBUG[7586][C-00000669] audiohook.c: Read factory 0x7fb54006d568 and write factory 0x7fb54006dfa8 both fail to provide 160 samples
[2020-01-20 14:25:59.472] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.472] DEBUG[7586][C-00000669] audiohook.c: Write factory 0x7fb54006dfa8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.472] DEBUG[7534][C-00000669] audiohook.c: Write factory 0x7fb54008fd18 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.474] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.475] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.475] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: Allocating new SIP dialog for 7cb44ba922d711791467b4da740d11b7@172.25.220.22:5060 - OPTIONS (No RTP)
[2020-01-20 14:25:59.476] DEBUG[80302] acl.c: For destination '10.119.220.214', our source address is '172.25.220.18'.
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: Setting AST_TRANSPORT_UDP with address 172.25.220.18:5060
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: SIP call-id changed from '7cb44ba922d711791467b4da740d11b7@172.25.220.22:5060' to '13c847a5472f15c459b0a3e06b88f3fe@172.25.220.18:5060'
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: Initializing initreq for method OPTIONS - callid 13c847a5472f15c459b0a3e06b88f3fe@172.25.220.18:5060
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.119.220.214:5060
[2020-01-20 14:25:59.476] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.477] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.479] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples
[2020-01-20 14:25:59.481] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.481] DEBUG[9097][C-000006bf] audiohook.c: Failed to get 160 samples from write factory 0x7fb53400d9c8
[2020-01-20 14:25:59.481] DEBUG[9097][C-000006bf] audiohook.c: Read factory 0x7fb53400cf88 and write factory 0x7fb53400d9c8 both fail to provide 160 samples
[2020-01-20 14:25:59.482] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.484] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.485] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.489] DEBUG[8400][C-000006a2] audiohook.c: Write factory 0x7fb5506c41e8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.491] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.492] DEBUG[7534][C-00000669] audiohook.c: Read factory 0x7fb54008f2d8 and write factory 0x7fb54008fd18 both fail to provide 160 samples
[2020-01-20 14:25:59.492] DEBUG[7586][C-00000669] audiohook.c: Read factory 0x7fb54006d568 and write factory 0x7fb54006dfa8 both fail to provide 160 samples
[2020-01-20 14:25:59.492] DEBUG[7586][C-00000669] audiohook.c: Write factory 0x7fb54006dfa8 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.492] DEBUG[7534][C-00000669] audiohook.c: Write factory 0x7fb54008fd18 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.494] DEBUG[8735][C-000006b1] audiohook.c: Read factory 0x7fb54c05d6a8 and write factory 0x7fb54c05e0e8 both fail to provide 160 samples
[2020-01-20 14:25:59.495] DEBUG[7077][C-0000066c] audiohook.c: Write factory 0x7fb54c048c28 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.496] DEBUG[5898][C-00000646] audiohook.c: Write factory 0x7fb564038808 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.496] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.497] DEBUG[9047][C-000006ba] audiohook.c: Read factory 0x7fb540026508 was pretty quick last time, waiting for them.
[2020-01-20 14:25:59.499] DEBUG[8750][C-000006b2] audiohook.c: Read factory 0x7fb554043408 and write factory 0x7fb554043e48 both fail to provide 160 samples

At restart time 16:28:53 System was logging a call with Jason calling voicemail the second prior we seem to be logging multiple events to the Channel event data.

[2020-01-20 16:28:36.904] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47221, detail:
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47221': 0x2d45df0 created
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Creating topic. name: cache:52130/channel:1579559316.47221, detail:
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Topic 'cache:52130/channel:1579559316.47221': 0x2a3cf10 created
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Destroying topic. name: cache:52130/channel:1579559316.47221, detail:
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Topic 'cache:52130/channel:1579559316.47221': 0x2a3cf10 destroyed
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579559316.47221, detail:
[2020-01-20 16:28:36.904] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47221': 0x2d45df0 destroyed
[2020-01-20 16:28:36.904] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 16:28:36.904] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('HANGUP', {ts '2020-01-20 16:28:36.531038'}, '', 'MSfuel: fuel: WIRELESS CALLER', '5154236178', '5154236178', '', '9133483976', 'h', 'queues', 'SIP/ec2-tel36-000012bf', '', '', 3, '', '', '1579558191.46187', '1579558191.46187', '', '')]
[2020-01-20 16:28:36.907] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47222, detail:
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47222': 0x2a70400 created
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Creating topic. name: cache:52131/channel:1579559316.47222, detail:
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Topic 'cache:52131/channel:1579559316.47222': 0x2cfd2b0 created
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Destroying topic. name: cache:52131/channel:1579559316.47222, detail:
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Topic 'cache:52131/channel:1579559316.47222': 0x2cfd2b0 destroyed
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579559316.47222, detail:
[2020-01-20 16:28:36.907] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47222': 0x2a70400 destroyed
[2020-01-20 16:28:36.907] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 16:28:36.907] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('CHAN_END', {ts '2020-01-20 16:28:36.531054'}, '', 'MSfuel: fuel: WIRELESS CALLER', '5154236178', '5154236178', '', '9133483976', 'h', 'queues', 'SIP/ec2-tel36-000012bf', '', '', 3, '', '', '1579558191.46187', '1579558191.46187', '', '')]
[2020-01-20 16:28:36.910] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47223, detail:
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47223': 0x2d5b620 created
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Creating topic. name: cache:52132/channel:1579559316.47223, detail:
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Topic 'cache:52132/channel:1579559316.47223': 0x2a76410 created
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Destroying topic. name: cache:52132/channel:1579559316.47223, detail:
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Topic 'cache:52132/channel:1579559316.47223': 0x2a76410 destroyed
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579559316.47223, detail:
[2020-01-20 16:28:36.910] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47223': 0x2d5b620 destroyed
[2020-01-20 16:28:36.911] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 16:28:36.911] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('LINKEDID_END', {ts '2020-01-20 16:28:36.531054'}, '', 'MSfuel: fuel: WIRELESS CALLER', '5154236178', '5154236178', '', '9133483976', 'h', 'queues', 'SIP/ec2-tel36-000012bf', '', '', 3, '', '', '1579558191.46187', '1579558191.46187', '', '')]
[2020-01-20 16:28:36.914] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47224, detail:
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47224': 0x2bb7d40 created
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Creating topic. name: cache:52133/channel:1579559316.47224, detail:
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Topic 'cache:52133/channel:1579559316.47224': 0x2d3ce30 created
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Destroying topic. name: cache:52133/channel:1579559316.47224, detail:
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Topic 'cache:52133/channel:1579559316.47224': 0x2d3ce30 destroyed
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579559316.47224, detail:
[2020-01-20 16:28:36.914] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47224': 0x2bb7d40 destroyed
[2020-01-20 16:28:36.914] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 16:28:36.914] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('HANGUP', {ts '2020-01-20 16:28:36.535577'}, '', 'GM-DealerGM-: ADVANTAGE CHEVY', '+17082152392', '+17082152392', '', '+19132675027', 'h', 'queues', 'SIP/opmgw23-00001275', '', '', 3, '', '', '1579557980.45583', '1579557980.45583', '', '')]
[2020-01-20 16:28:36.917] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47225, detail:
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47225': 0x2a2d300 created
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Creating topic. name: cache:52134/channel:1579559316.47225, detail:
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Topic 'cache:52134/channel:1579559316.47225': 0x2a87420 created
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Destroying topic. name: cache:52134/channel:1579559316.47225, detail:
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Topic 'cache:52134/channel:1579559316.47225': 0x2a87420 destroyed
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Destroying topic. name: channel:1579559316.47225, detail:
[2020-01-20 16:28:36.917] DEBUG[80279] stasis.c: Topic 'channel:1579559316.47225': 0x2a2d300 destroyed
[2020-01-20 16:28:36.917] DEBUG[80279] res_odbc.c: Reusing ODBC handle 0x12a3710 from class 'cel'
[2020-01-20 16:28:36.917] DEBUG[80279] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype, eventtime, userdeftype, cid_name, cid_num, cid_ani, cid_rdnis, cid_dnid, exten, context, channame, appname, appdata, amaflags, accountcode, peeraccount, uniqueid, linkedid, userfield, peer) VALUES ('CHAN_END', {ts '2020-01-20 16:28:36.535636'}, '', 'GM-DealerGM-: ADVANTAGE CHEVY', '+17082152392', '+17082152392', '', '+19132675027', 'h', 'queues', 'SIP/opmgw23-00001275', '', '', 3, '', '', '1579557980.45583', '1579557980.45583', '', '')]
[2020-01-20 16:28:36.920] DEBUG[80279] res_odbc.c: Releasing ODBC handle 0x12a3710 into pool
[2020-01-20 16:28:36.920] DEBUG[80279] stasis.c: Creating topic. name: channel:1579559316.47226, detail:

[2020-01-20 16:28:53.076] DEBUG[40646] cdr.c: Finalized CDR for SIP/Jason-Troutner-00001316 - start 1579558479.989256 answer 1579558479.991097 end 1579558481.492130 dispo ANSWERED
[2020-01-20 16:28:53.076] DEBUG[40646] res_odbc.c: Reusing ODBC handle 0x7fb56c0082d0 from class 'cdr'
[2020-01-20 16:28:53.076] DEBUG[40646] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (start, answer, end, dnid, clid, src, dst, dcontext, channel, lastapp, lastdata, duration, billsec, disposition, amaflags, uniqueid, linkedid, sequence) VALUES ({ ts '2020-01-20 16:14:39' }, { ts '2020-01-20 16:14:39' }, { ts '2020-01-20 16:14:41' }, '31801', '"Jason Troutner" <32641>', '32641', '31801', 'stations', 'SIP/Jason-Troutner-00001316', 'VoiceMailMain', '32641@stations', 1, 1, 'ANSWERED', 3, '1579558479.46964', '1579558479.46964', '6272')]
[2020-01-20 16:28:53.080] DEBUG[40646] res_odbc.c: Releasing ODBC handle 0x7fb56c0082d0 into pool
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Creating topic. name: channel:1579559333.47230, detail:
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Topic 'channel:1579559333.47230': 0x7fb54002e970 created
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Creating topic. name: cache:52139/channel:1579559333.47230, detail:
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Topic 'cache:52139/channel:1579559333.47230': 0x7fb540088d10 created
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Destroying topic. name: cache:52139/channel:1579559333.47230, detail:
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Topic 'cache:52139/channel:1579559333.47230': 0x7fb540088d10 destroyed
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Destroying topic. name: channel:1579559333.47230, detail:
[2020-01-20 16:28:53.080] DEBUG[40646] stasis.c: Topic 'channel:1579559333.47230': 0x7fb54002e970 destroyed
[2020-01-20 16:28:53.080] DEBUG[80357] manager.c: Examining AMI event:
Event: Cdr
Privilege: cdr,all
AccountCode:
Source: 32641
Destination: 31801
DestinationContext: stations
CallerID: "Jason Troutner" <32641>
Channel: SIP/Jason-Troutner-00001316
DestinationChannel:
LastApplication: VoiceMailMain
LastData: 32641@stations
StartTime: 2020-01-20 16:14:39
AnswerTime: 2020-01-20 16:14:39
EndTime: 2020-01-20 16:14:41
Duration: 1
BillableSeconds: 1
Disposition: ANSWERED
AMAFlags: DOCUMENTATION
UniqueID: 1579558479.46964
UserField:

[2020-01-20 16:28:53.081] DEBUG[40646] asterisk.c: Asterisk ending (0).
{noformat}
By: Dan (dwsiemens) 2020-01-20 20:37:28.102-0600

So looks like I may have some sort of codec frame issue along the way but Not sure if that would be the source.
Next time I'm in front of it I'll so a show peers but i'm sure when I've done this in the past Its shown them with current registraton times not offline But for sure the endpoints were unhappy.
By: Dan (dwsiemens) 2020-01-29 09:43:37.874-0600

My phone lost connection,

The sip show peers shows its still registered
dwsiemens/dwsiemens 10.119.101.242 D No No A 5060 OK (140 ms)
By: Sean Bright (seanbright) 2020-01-29 09:46:25.861-0600

chan_sip is community supported, so if a problem does exist there is no timeframe on when it will get looked into or even if it will. I would strongly suggest that you upgrade to chan_pjsip.
By: Benjamin Keith Ford (bford) 2020-01-29 09:55:46.239-0600

The chan_sip channel driver is in 'extended' support status and is supported only by community members. Your issue is in the queue. Your patience is appreciated as a community developer may work the issue when time and resources become available.

Asterisk is an open source project and community members work the issues on a voluntary basis. You are welcome to develop your own patches and submit them to the project.[1]

If you are not a programmer and you are in a hurry to see a patch provided then you might try rallying support on the Asterisk users mailing list or forums.[2] Another alternative is offering a bug bounty on the asterisk-dev mailing list.[3] Often a little incentive can go a long way.

[1]: https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process
[2]: http://www.asterisk.org/community/discuss
[3]: https://wiki.asterisk.org/wiki/display/AST/Asterisk+Bug+Bounties

By: Dan (dwsiemens) 2020-01-29 11:11:41.687-0600

Its about as bad as it gets when you drop 50 phone calls everytime this happens.

Converting to pjsip is a major undertaking but looking at it. Have some new hosts I'll be installing a test on.

Whats also interesting is that New chan sip calls from other asterisk boxes continue to come into the system. Its the end points that loose it, not other server to server over sip.

By: Dan (dwsiemens) 2020-01-30 15:33:01.174-0600

Had it happen again.

I told it to do a sip set debug on Whats interesting is this is one of a few users set to tcp. 99% are udp not tcp. Not sure if this has something to do with it.

<--- SIP read from TCP:10.119.102.37:53305 --->
REGISTER sip:172.25.220.18;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 10.119.102.37:62384;branch=z9hG4bK-524287-1---10bb43e4dd97cbd1;rport
Max-Forwards: 70
Contact: <sip:tgarcia@10.119.102.37:62384;transport=TCP;rinstance=08ed283c294cc901>
To: <sip:tgarcia@172.25.220.18;transport=TCP>
From: <sip:tgarcia@172.25.220.18;transport=TCP>;tag=312fe032
Call-ID: gcKoE6J2BIHTntHccZtTSg..
CSeq: 15 REGISTER
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
User-Agent: Z 5.2.25 rv2.8.112
Allow-Events: presence, kpml, talk
Content-Length: 0

In sip show peers I had
cia/tgarcia 10.119.102.37 D No No A 5060 OK (166 ms) Cached RT

My phone had an X on the display and it was showing as Daniel-Siemens/Daniel-Sie 10.119.220.166 D No No A 5060 OK (75 ms) Cached RT

By: Dan (dwsiemens) 2020-01-30 16:04:14.313-0600

So questions, Could this be a UDP only issue? I'm going to up the receive window.
I've lost 342190 packets.
Udp:
1247999928 packets received
1032070 packets to unknown port received.
342190 packet receive errors
1269965803 packets sent
342190 receive buffer errors
0 send buffer errors

Anything else or other ideas?

By: Dan (dwsiemens) 2020-02-05 07:28:08.467-0600

I've worked with Redhat on the issue, I'm pasting in notes from the ticket,

In mpstat we don't have any high CPU usage, these samples are pretty typical for the problem duration:

{noformat}
===== 2020-02-04 14:44:17.183137666-06:00 (CST) =====
Linux 3.10.0-1062.9.1.el7.x86_64 (vmctel22.multiservice.com) 02/04/2020 _x86_64_ (2 CPU)

02:44:17 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
02:44:17 PM all 3.78 0.04 2.21 0.03 0.00 0.22 0.00 0.00 0.00 93.73
02:44:17 PM 0 4.07 0.04 2.25 0.03 0.00 0.22 0.00 0.00 0.00 93.40
02:44:17 PM 1 3.49 0.04 2.16 0.03 0.00 0.22 0.00 0.00 0.00 94.07
--
===== 2020-02-04 14:44:27.689970043-06:00 (CST) =====
Linux 3.10.0-1062.9.1.el7.x86_64 (vmctel22.multiservice.com) 02/04/2020 _x86_64_ (2 CPU)

02:44:27 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
02:44:27 PM all 3.78 0.04 2.21 0.03 0.00 0.22 0.00 0.00 0.00 93.73
02:44:27 PM 0 4.07 0.04 2.25 0.03 0.00 0.22 0.00 0.00 0.00 93.40
02:44:27 PM 1 3.49 0.04 2.16 0.03 0.00 0.22 0.00 0.00 0.00 94.07

....

===== 2020-02-04 14:51:49.046385591-06:00 (CST) =====
Linux 3.10.0-1062.9.1.el7.x86_64 (vmctel22.multiservice.com) 02/04/2020 _x86_64_ (2 CPU)

02:51:49 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
02:51:49 PM all 3.78 0.04 2.21 0.03 0.00 0.22 0.00 0.00 0.00 93.73
02:51:49 PM 0 4.07 0.04 2.25 0.03 0.00 0.22 0.00 0.00 0.00 93.40
02:51:49 PM 1 3.49 0.04 2.16 0.03 0.00 0.22 0.00 0.00 0.00 94.07
--
===== 2020-02-04 14:51:59.576578097-06:00 (CST) =====
Linux 3.10.0-1062.9.1.el7.x86_64 (vmctel22.multiservice.com) 02/04/2020 _x86_64_ (2 CPU)

02:51:59 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
02:51:59 PM all 3.78 0.04 2.21 0.03 0.00 0.22 0.00 0.00 0.00 93.73
02:51:59 PM 0 4.07 0.04 2.25 0.03 0.00 0.22 0.00 0.00 0.00 93.40
02:51:59 PM 1 3.49 0.04 2.16 0.03 0.00 0.22 0.00 0.00 0.00 94.07
{noformat}

Looking in netstat, we see the UDP receive buffer errors start to grow at this time:

{noformat}
===== 2020-02-04 14:44:06.543609549-06:00 (CST) =====
498235 packet receive errors
498235 receive buffer errors
===== 2020-02-04 14:44:17.097980110-06:00 (CST) =====
498235 packet receive errors
498235 receive buffer errors
===== 2020-02-04 14:44:27.612813403-06:00 (CST) =====
498288 packet receive errors
498288 receive buffer errors
===== 2020-02-04 14:44:38.117369314-06:00 (CST) =====
498737 packet receive errors
498737 receive buffer errors
...
===== 2020-02-04 14:51:48.952477580-06:00 (CST) =====
539529 packet receive errors
539529 receive buffer errors
===== 2020-02-04 14:51:59.475876814-06:00 (CST) =====
540605 packet receive errors
540605 receive buffer errors
===== 2020-02-04 14:52:09.984118121-06:00 (CST) =====
541476 packet receive errors
541476 receive buffer errors
===== 2020-02-04 14:52:20.524792598-06:00 (CST) =====
541476 packet receive errors
541476 receive buffer errors
{noformat}

Looking in ss, we can correlate the "receive buffer errors" with the asterisk PID's receive buffers growing large on the same, and growing, set of file descriptors:

{noformat}
===== 2020-02-04 14:43:45.551605758-06:00 (CST) =====
udp UNCONN 169728 0 *:5060 *:* users:(("asterisk",pid=60277,fd=25))
udp UNCONN 8704 0 *:13900 *:* users:(("asterisk",pid=60277,fd=448))
udp UNCONN 2176 0 *:13901 *:* users:(("asterisk",pid=60277,fd=451))
===== 2020-02-04 14:43:56.047824912-06:00 (CST) =====
udp UNCONN 578816 0 *:5060 *:* users:(("asterisk",pid=60277,fd=25))
udp UNCONN 8704 0 *:13900 *:* users:(("asterisk",pid=60277,fd=448))
udp UNCONN 2176 0 *:13901 *:* users:(("asterisk",pid=60277,fd=451))
udp UNCONN 2176 0 *:18306 *:* users:(("asterisk",pid=60277,fd=322))
===== 2020-02-04 14:44:06.551862862-06:00 (CST) =====
udp UNCONN 404736 0 *:15844 *:* users:(("asterisk",pid=60277,fd=389))
udp UNCONN 2176 0 *:15845 *:* users:(("asterisk",pid=60277,fd=452))
udp UNCONN 1129344 0 *:5060 *:* users:(("asterisk",pid=60277,fd=25))
udp UNCONN 8704 0 *:13900 *:* users:(("asterisk",pid=60277,fd=448))
udp UNCONN 2176 0 *:13901 *:* users:(("asterisk",pid=60277,fd=451))
{noformat}

Mike's notes showed these growing to their maximum size, which is when traffic will drop and the "receive buffer error" stat will grow.

We also have a number of samples where asterisk's TCP sockets are sitting in CLOSE_WAIT, indicating the remote end has sent a FIN (which the kernel has ACKed) and we're waiting for the socket owner process (asterisk) to realise that's happened and to close its socket as well:

{noformat}
===== 2020-02-04 14:45:41.206873257-06:00 (CST) =====
tcp CLOSE-WAIT 1 0 172.25.220.22:43002 172.25.220.22:3306 users:(("asterisk",pid=60277,fd=10))
tcp CLOSE-WAIT 1 0 172.25.220.18:5060 10.119.220.220:63729 users:(("asterisk",pid=60277,fd=167))
tcp ESTAB 757 0 172.25.220.18:5060 10.119.102.102:54234 users:(("asterisk",pid=60277,fd=589))
tcp CLOSE-WAIT 1 0 172.25.220.18:5060 10.119.220.166:60249 users:(("asterisk",pid=60277,fd=189))
tcp CLOSE-WAIT 1 0 172.25.220.22:34332 172.25.220.22:3306 users:(("asterisk",pid=60277,fd=11))
tcp CLOSE-WAIT 1 0 172.25.220.18:5060 10.119.221.63:51439 users:(("asterisk",pid=60277,fd=64))
tcp CLOSE-WAIT 1 0 172.25.220.18:5060 10.119.220.237:48159 users:(("asterisk",pid=60277,fd=146))
{noformat}

All taken together, this is strong evidence that there is no system bottleneck, but the root cause is that the Asterisk process is doing something else instead of handling its network sockets.

The next step is to debug Asterisk to find out what it's doing at the problem times and why it's doing that, with the aim to get Asterisk back to doing the work it should be doing instead.

As Asterisk is not software which Red Hat supply or support, please refer this issue to your technical support for Asterisk.

By: Dan (dwsiemens) 2020-02-07 13:57:02.161-0600

I've tried to downgrade to Asterisk 13.30 in hopes it doesn't' have this issue.
By: Dan (dwsiemens) 2020-02-11 08:48:36.205-0600

Same issue occurs in Asterisk 13.31