[asterisk-bugs] [JIRA] (ASTERISK-28705) chan_sip: Phones loose abiltiy to work, core restarting asterisk fixes issue
Dan (JIRA)
noreply at issues.asterisk.org
Mon Jan 20 20:36:39 CST 2020
[ https://issues.asterisk.org/jira/browse/ASTERISK-28705?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=249492#comment-249492 ]
Dan commented on ASTERISK-28705:
---------------------------------
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
[2020-01-20 14:16:01.410] DEBUG[80357] manager.c: Examining AMI event:
Event: VarSet
Privilege: dialplan,all
Channel: Local/0 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 172.25.220.22:5060' to '13c847a5472f15c459b0a3e06b88f3fe at 172.25.220.18:5060'
[2020-01-20 14:25:59.476] DEBUG[80302] chan_sip.c: Initializing initreq for method OPTIONS - callid 13c847a5472f15c459b0a3e06b88f3fe at 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 at 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 at 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).
> chan_sip: Phones loose abiltiy to work, core restarting asterisk fixes issue
> -----------------------------------------------------------------------------
>
> Key: ASTERISK-28705
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-28705
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Channels/chan_sip/General
> Affects Versions: 16.7.0
> Environment: I have a Redhat HA cluster running with 2 Rhel 7 nodes with asterisk 16.7.0
> Reporter: Dan
> Assignee: Unassigned
>
> 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
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list