[App_rpt-users] asterisk crashing

Bryan Fields Bryan at bryanfields.net
Fri Jun 24 23:18:14 UTC 2016 

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


-- 
Bryan Fields

727-409-1194 - Voice
727-214-2508 - Fax
http://bryanfields.net

More information about the App_rpt-users mailing list