[App_rpt-users] asterisk crashing

Fri Jun 24 23:31:19 UTC 2016

I have had this happen twice in about 3 weeks.  Dell PC / ACID 
distribution / 2 URIx.  I know the software restarted because I have a 
message play from the start-marco.

...STeve - KF5VH

On 6/24/2016 6:18 PM, Bryan Fields wrote:
> On 6/15/16 3:59 PM, Bryan Fields wrote:
>> I've had asterisk crash twice over the past few weeks.  I can't see any
>> obvious problems in the logging.  I've enabled debug logging and will see what
>> I can find out when/if it happens again.
> It crashed last night!  The only common theme I see is Echolink connected and
> then it had an error of sorts.
>
> Has anyone been seeing asterisk crashes related to this?
>
> channel.c: Thread -1260881088 Blocking 'echolink/el0-0', already blocked by
> thread -1257419968 in procedure ast_waitfor_nandfds
>
> It then dies after that message.  I do have detailed logs if needed I can post
> them on a web server.
>
>
>> [Jun 24 00:17:21] DEBUG[26077] chan_iax2.c: Registration created on call 4900
>> [Jun 24 00:17:21] WARNING[26080] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:17:21] DEBUG[26076] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:17:27] DEBUG[26079] chan_iax2.c: Received iseqno 182 not within window 183->183
>> [Jun 24 00:17:27] DEBUG[26085] chan_iax2.c: ip callno count decremented to 4 for 67.215.233.178
>> [Jun 24 00:17:31] DEBUG[26085] chan_iax2.c: ip callno count decremented to 3 for 67.215.233.178
>> [Jun 24 00:17:41] VERBOSE[26064] logger.c:   == Refreshing DNS lookups.
>> [Jun 24 00:17:43] DEBUG[26077] chan_iax2.c: Received iseqno 220 not within window 221->221
>> [Jun 24 00:17:47] DEBUG[26077] chan_iax2.c: Received iseqno 14 not within window 15->15
>> [Jun 24 00:17:47] WARNING[26082] chan_iax2.c: REGISTER-LOG: Sending registration request for '40821'
>> [Jun 24 00:17:47] DEBUG[26082] chan_iax2.c: Allocate call number
>> [Jun 24 00:17:47] DEBUG[26082] chan_iax2.c: ip callno count incremented to 4 for 67.215.233.178
>> [Jun 24 00:17:47] DEBUG[26082] chan_iax2.c: Registration created on call 7527
>> [Jun 24 00:17:48] WARNING[26079] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:17:48] DEBUG[26080] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:17:53] DEBUG[26080] chan_iax2.c: Received iseqno 232 not within window 233->233
>> [Jun 24 00:17:54] DEBUG[26078] chan_iax2.c: Received iseqno 225 not within window 226->226
>> [Jun 24 00:17:57] DEBUG[26085] chan_iax2.c: ip callno count decremented to 3 for 67.215.233.178
>> [Jun 24 00:18:07] WARNING[26079] chan_iax2.c: REGISTER-LOG: Sending registration request for '42032'
>> [Jun 24 00:18:07] DEBUG[26079] chan_iax2.c: Allocate call number
>> [Jun 24 00:18:07] DEBUG[26079] chan_iax2.c: ip callno count incremented to 4 for 67.215.233.178
>> [Jun 24 00:18:07] DEBUG[26079] chan_iax2.c: Registration created on call 8176
>> [Jun 24 00:18:07] WARNING[26076] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:18:07] DEBUG[26080] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:18:11] WARNING[26076] chan_iax2.c: REGISTER-LOG: Sending registration request for '41618'
>> [Jun 24 00:18:11] DEBUG[26076] chan_iax2.c: Allocate call number
>> [Jun 24 00:18:11] DEBUG[26076] chan_iax2.c: ip callno count incremented to 5 for 67.215.233.178
>> [Jun 24 00:18:11] DEBUG[26076] chan_iax2.c: Registration created on call 6735
>> [Jun 24 00:18:12] WARNING[26075] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:18:12] DEBUG[26078] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:18:15] DEBUG[26084] chan_iax2.c: Received iseqno 241 not within window 242->242
>> [Jun 24 00:18:17] DEBUG[26085] chan_iax2.c: ip callno count decremented to 4 for 67.215.233.178
>> [Jun 24 00:18:21] DEBUG[26085] chan_iax2.c: ip callno count decremented to 3 for 67.215.233.178
>> [Jun 24 00:18:23] DEBUG[26082] chan_iax2.c: Received iseqno 244 not within window 245->245
>> [Jun 24 00:18:33] DEBUG[26075] chan_iax2.c: Received iseqno 247 not within window 248->248
>> [Jun 24 00:18:36] VERBOSE[26072] logger.c:     -- Received OK from Echolink server nasouth.echolink.org
>> [Jun 24 00:18:38] WARNING[26083] chan_iax2.c: REGISTER-LOG: Sending registration request for '40821'
>> [Jun 24 00:18:38] DEBUG[26083] chan_iax2.c: Allocate call number
>> [Jun 24 00:18:38] DEBUG[26083] chan_iax2.c: ip callno count incremented to 4 for 67.215.233.178
>> [Jun 24 00:18:38] DEBUG[26083] chan_iax2.c: Registration created on call 9504
>> [Jun 24 00:18:38] WARNING[26084] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:18:38] DEBUG[26082] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:18:43] DEBUG[26084] chan_iax2.c: Received iseqno 252 not within window 253->253
>> [Jun 24 00:18:48] DEBUG[26085] chan_iax2.c: ip callno count decremented to 3 for 67.215.233.178
>> [Jun 24 00:18:53] DEBUG[26083] chan_iax2.c: Received iseqno 254 not within window 255->255
>> [Jun 24 00:18:57] WARNING[26081] chan_iax2.c: REGISTER-LOG: Sending registration request for '42032'
>> [Jun 24 00:18:57] DEBUG[26081] chan_iax2.c: Allocate call number
>> [Jun 24 00:18:57] DEBUG[26081] chan_iax2.c: ip callno count incremented to 4 for 67.215.233.178
>> [Jun 24 00:18:57] DEBUG[26081] chan_iax2.c: Registration created on call 14887
>> [Jun 24 00:18:58] WARNING[26084] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:18:58] DEBUG[26076] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:19:02] WARNING[26078] chan_iax2.c: REGISTER-LOG: Sending registration request for '41618'
>> [Jun 24 00:19:02] DEBUG[26078] chan_iax2.c: Allocate call number
>> [Jun 24 00:19:02] DEBUG[26078] chan_iax2.c: ip callno count incremented to 5 for 67.215.233.178
>> [Jun 24 00:19:02] DEBUG[26078] chan_iax2.c: Registration created on call 5474
>> [Jun 24 00:19:02] WARNING[26080] chan_iax2.c: REGISTER-LOG: registry rereqquest
>> [Jun 24 00:19:02] DEBUG[26075] chan_iax2.c: schedule decrement of callno used for 67.215.233.178 in 60 seconds
>> [Jun 24 00:19:03] DEBUG[26083] chan_iax2.c: Received iseqno 3 not within window 4->4
>> [Jun 24 00:19:06] DEBUG[26084] chan_iax2.c: Received iseqno 218 not within window 219->219
>> [Jun 24 00:19:06] VERBOSE[26073] logger.c:     -- new CALL=RV9CN,ip=44.137.75.155,name=        Slava
>> [Jun 24 00:19:06] DEBUG[15005] pbx.c: Launching 'Rpt'
>> [Jun 24 00:19:06] VERBOSE[15005] logger.c:     -- Executing [40821 at radio-secure:1] Rpt("echolink/el0-0", "40821") in new stack
>> [Jun 24 00:19:06] DEBUG[15005] channel.c: Set channel echolink/el0-0 to read format slin
>> [Jun 24 00:19:06] DEBUG[15005] channel.c: Set channel echolink/el0-0 to write format slin
>> [Jun 24 00:19:06] DEBUG[15005] chan_dahdi.c: Using channel -2
>> [Jun 24 00:19:06] DEBUG[15005] channel.c: Set channel DAHDI/pseudo-1265695481 to read format slin
>> [Jun 24 00:19:06] DEBUG[15005] channel.c: Set channel DAHDI/pseudo-1265695481 to write format slin
>> [Jun 24 00:19:06] DEBUG[15005] devicestate.c: Notification of state change to be queued on device/channel echolink/el0
>> [Jun 24 00:19:06] DEBUG[26066] devicestate.c: No provider found, checking channel drivers for echolink - el0
>> [Jun 24 00:19:06] DEBUG[26066] devicestate.c: Changing state for echolink/el0 - state 2 (In use)
>> [Jun 24 00:19:06] DEBUG[15005] channel.c: Thread -1260881088 Blocking 'echolink/el0-0', already blocked by thread -1257419968 in procedure ast_waitfor_nandfds
>> [Jun 24 00:19:06] DEBUG[15005] pbx.c: Spawn extension (radio-secure,40821,1) exited KEEPALIVE on 'echolink/el0-0'
>> [Jun 24 00:19:06] VERBOSE[15005] logger.c:   == Spawn extension (radio-secure, 40821, 1) exited KEEPALIVE on 'echolink/el0-0'
>> [Jun 24 00:19:07] DEBUG[26089] channel.c: Ignoring answer on an inbound call!
>> [Jun 24 00:19:07] DEBUG[26085] chan_iax2.c: ip callno count decremented to 4 for 67.215.233.178
>> [Jun 24 00:19:11] VERBOSE[26074] logger.c:     -- Received OK from Echolink server servers.echolink.org
>> [Jun 24 00:19:11] VERBOSE[26072] logger.c:     -- Received OK from Echolink server servers.echolink.org
>> [Jun 24 00:19:12] DEBUG[26085] chan_iax2.c: ip callno count decremented to 3 for 67.215.233.178
>> [Jun 24 00:19:13] DEBUG[26080] chan_iax2.c: Received iseqno 6 not within window 7->7
>> [Jun 24 00:19:17] DEBUG[26075] chan_iax2.c: Received iseqno 47 not within window 48->48
>
> Output from the CLI in screen is below.  It mirrors the logs.
>
>
>
>    -- new CALL=RV9CN,ip=44.137.75.155,name=        Slava
>      -- Executing [40821 at radio-secure:1] Rpt("echolink/el0-0", "40821") in new
> stack
> Node Variable dump for node 40821:
>     RPT_NUMLINKS=49
>
> RPT_LINKS=49,T41618,T3685739,T42032,T41170,T27714,T41599,T42462,T29826,T29901,T29902,T41508,T29771,T27455,T29772,T29827,T43309,T41510,T41629,T28073,T2578,T28183,T41535,T29227,T29474,T29475,T42978,T41385,TN7GLV,T42610,T41373,T27654,T29521,T29522,T41688,T1980,T3630564,T42574,T41525,T42393,T1976,T29658,T42205,T41237,T40603,T29659,T42947,T40696,T42215,T40562
>     RPT_NUMALINKS=3
>     RPT_ALINKS=3,41618TU,3685739TU,42032TU
>     RPT_TXKEYED=0
>     RPT_ETXKEYED=0
>     RPT_RXKEYED=0
>     RPT_AUTOPATCHUP=0
>      -- 10 variables
>    == Spawn extension (radio-secure, 40821, 1) exited KEEPALIVE on 'echolink/el0-0'
>      -- Received OK from Echolink server servers.echolink.org
>      -- Received OK from Echolink server servers.echolink.org
> Itchy*CLI>
> Disconnected from Asterisk server
> Executing last minute cleanups
> Asterisk ending (0).
>
>