Summary: | ASTERISK-01784: PRI busy state confusion | ||
Reporter: | trmckee3 (trmckee3) | Labels: | |
Date Opened: | 2004-06-09 07:49:27 | Date Closed: | 2004-09-25 02:26:27 |
Priority: | Major | Regression? | No |
Status: | Closed/Complete | Components: | Core/General |
Versions: | Frequency of Occurrence | ||
Related Issues: | |||
Environment: | Attachments: | ||
Description: | system will suddenly and randomly disallow inbound calls on the pri. Outbound calls seem to be allowed normally. Pri is to a Nortel DMS500. service asterisk stop/start clears the error, a restart of zaptel is not required. Here is the console output: Jun 9 07:17:22 WARNING[1142135600]: chan_sip.c:2503 process_sdp: No compatible codecs! -- Executing Dial("SIP/ATA1001.1-f0a9", "Zap/g2/18282158584|40") in new stack -- Called g2/18282158584 -- Zap/26-1 answered SIP/ATA1001.1-f0a9 -- Channel 0/2, span 2 got hangup -- Hungup 'Zap/26-1' == Spawn extension (dialnational, 918282158584, 1) exited non-zero on 'SIP/ATA1001.1-f0a9' Jun 9 07:20:15 WARNING[1142135600]: chan_sip.c:2503 process_sdp: No compatible codecs! Jun 9 07:20:16 WARNING[1142135600]: chan_sip.c:2503 process_sdp: No compatible codecs! -- Executing Dial("SIP/ATA1001.1-a918", "Zap/g2/18282158584|40") in new stack -- Called g2/18282158584 -- Zap/26-1 answered SIP/ATA1001.1-a918 -- Channel 0/2, span 2 got hangup -- Hungup 'Zap/26-1' == Spawn extension (dialnational, 918282158584, 1) exited non-zero on 'SIP/ATA1001.1-a918' Jun 9 07:34:21 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:34:35 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:34:53 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:40:34 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:40:38 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:40:44 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:00 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:04 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:07 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:11 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:13 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:15 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:17 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:19 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:21 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:23 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:34 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:37 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:41:43 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:00 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:02 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:04 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:06 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:09 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:12 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:19 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:36 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:38 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 07:42:41 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. ****** STEPS TO REPRODUCE ****** unknown triggers ****** ADDITIONAL INFORMATION ****** production pbx - contact me for read access ZAPATA.CONF: [root@pbx1 asterisk]# more zapata.conf ; ; Zapata telephony interface ; ; Configuration file [channels] use_callerid=yes callwaiting=no restrictcid=no usecallingpres=yes callwaitingcallerid=yes threewaycalling=yes transfer=yes cancallforward=yes callreturn=yes echocancel=yes echocancelwhenbridged=yes echotraining=yes relaxdtmf=no rxgain=0.0 txgain=0.0 callgroup=1 pickupgroup=1 immediate=no amaflags=billing accountcode=sdnclt ; ; Default language ; language=en ; NuVox PRI context=sdnpri ; switchtype = national pridialplan = unknown signalling = pri_cpe callerid=asreceived group = 2 channel => 25-47 | ||
Comments: | By: Mark Spencer (markster) 2004-06-09 08:38:44 Can you find me on IRC? I'll need to see the active calls when this happens, it sounds like there is a call that is "stuck" somehow. By: trmckee3 (trmckee3) 2004-06-09 09:30:09 I've set up a username pwd with ssh access to the box. I'll contact you on IRC to arrange transfer of info. By: trmckee3 (trmckee3) 2004-06-09 10:17:45 happened again, couldn't find you on #asterisk. had to reset. here is console output including a 'zap show channels'. Please note that the 'non-existant' call on the second line shows up in the show channels as active. == Spawn extension (dialintl, 918484597801, 1) exited non-zero on 'SIP/1511-4eab' -- Extension '7045874871' in context 'sdnpri' from '' does not exist. Rejecting call on channel 0/1, span 2 Jun 9 10:45:18 WARNING[1142135600]: chan_sip.c:2503 process_sdp: No compatible codecs! Jun 9 10:45:19 WARNING[1142135600]: chan_sip.c:2503 process_sdp: No compatible codecs! -- Executing Dial("SIP/ATA1001.1-ef23", "Zap/g2/17078490593|40") in new stack -- Called g2/17078490593 -- Executing Dial("SIP/ATA1001.1-cb06", "Zap/g2/17078490593|40") in new stack -- Called g2/17078490593 -- Zap/27-1 answered SIP/ATA1001.1-cb06 -- Hungup 'Zap/27-1' == Spawn extension (dialnational, 917078490593, 1) exited non-zero on 'SIP/ATA1001.1-cb06' -- Channel 0/1, span 2 got hangup == Spawn extension (macro-sdn2line, s, 1) exited non-zero on 'Zap/26-1' in macro 'sdn2line' == Spawn extension (sdnphones, 1321, 1) exited non-zero on 'Zap/26-1' -- Hungup 'Zap/26-1' -- Channel 0/1, span 2 got hangup Jun 9 10:46:23 NOTICE[1142135600]: chan_sip.c:6713 handle_request: Registration from 'ATA-1001:1 <sip:ATA1001.1@168.215.120.5>' failed for '168.215.120.49' Jun 9 10:46:23 NOTICE[1142135600]: chan_sip.c:6713 handle_request: Registration from 'ATA-1001:2 <sip:ATA1001.2@168.215.120.5>' failed for '168.215.120.49' Jun 9 10:47:50 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 10:48:10 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. -- Executing Macro("SIP/1031-3513", "sdn2line|1121|sip/1121|sip/1122") in new stack -- Executing Dial("SIP/1031-3513", "sip/1121|15|r") in new stack -- Called 1121 -- SIP/1121-ca38 is ringing -- Nobody picked up in 15000 ms -- Executing VoiceMail("SIP/1031-3513", "u1121") in new stack -- Playing 'voicemail/sdnphones/1121/unavail' (language 'en') == Spawn extension (macro-sdn2line, s, 2) exited non-zero on 'SIP/1031-3513' in macro 'sdn2line' == Spawn extension (dialnational, 1121, 1) exited non-zero on 'SIP/1031-3513' -- Executing Dial("SIP/1511-01bf", "Zap/g2/7045879199|40") in new stack -- Called g2/7045879199 -- Executing Dial("SIP/1211-c18c", "Zap/g2/16785927967|40") in new stack -- Called g2/16785927967 -- Hungup 'Zap/26-1' == Spawn extension (dialintl, 97045879199, 1) exited non-zero on 'SIP/1511-01bf' -- Executing Dial("SIP/1511-746f", "Zap/g2/7048759199|40") in new stack -- Called g2/7048759199 -- Zap/26-1 is ringing -- Nobody picked up in 40000 ms -- Hungup 'Zap/27-1' -- Zap/26-1 answered SIP/1511-746f Jun 9 10:52:42 WARNING[1234455344]: pbx.c:1870 ast_pbx_run: Timeout, but no rule 't' in context 'dialintl' -- Channel 0/2, span 2 got hangup -- Hungup 'Zap/26-1' == Spawn extension (dialintl, 97048759199, 1) exited non-zero on 'SIP/1511-746f' Jun 9 10:52:59 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 10:53:09 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 10:53:18 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 10:54:46 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. Jun 9 10:55:02 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. pbx1*CLI> zap show cadences channel channels Jun 9 10:55:13 WARNING[1184099120]: chan_zap.c:6941 pri_dchannel: Ring requested on channel 0/1 already in use on span 2. Hanging up owner. pbx1*CLI> zap show cchannels No such command 'zap show cchannels' (type 'help' for help) pbx1*CLI> zap show channels Chan Extension Context Language MusicOnHold pseudo dialnational en 25 7045874871 sdnpri en 26 sdnpri en 27 sdnpri en 28 sdnpri en 29 sdnpri en 30 sdnpri en 31 sdnpri en 32 sdnpri en 33 sdnpri en 34 sdnpri en 35 sdnpri en 36 sdnpri en 37 sdnpri en 38 sdnpri en 39 sdnpri en 40 sdnpri en 41 sdnpri en 42 sdnpri en 43 sdnpri en 44 sdnpri en 45 sdnpri en 46 sdnpri en 47 sdnpri en 49 dialnational en 50 dialnational en 51 dialnational en 52 dialnational en 53 dialnational en 54 dialnational en By: Mark Spencer (markster) 2004-06-09 10:24:05 This isn't what I need, unfortunately. i've been on IRC all morning, where are you looking? I'm in irc.freenode.net in #asterisk and #asterisk-bugs, and my nick is "kram". I will need "show channels" and "zap show channel 2" at a minimum but likely more than that. Also please be sure you're already updated to latest CVS head as of this morning. By: trmckee3 (trmckee3) 2004-06-09 10:53:04 ahhh.... I was looking for markster... wasn't aware of your 'kram' id. I went ahead and created extension definitions for each and every possible DID that go to the autoattendant menu, so I may have forestalled the problem temporarily. I will take the definitions off and try to recreate the problem after hours, running those show commands. Is there any other debug info you might need me to collect? Just in case you aren't around when it occurs or it happens at a critical time period.... By: Mark Spencer (markster) 2004-06-09 13:54:57 Okay, find me on IRC so we can schedule a time to be sure I will be available to perform the analysis when you get a chance. By: trmckee3 (trmckee3) 2004-06-09 14:05:27 Will do. It turns out it will be tomorrow before I can try. Things have been stable since I defined all the possible extensions, so it should be ok till then. By: Mark Spencer (markster) 2004-06-09 14:23:05 You may also call Digium to schedule an appointment. By: trmckee3 (trmckee3) 2004-06-11 08:50:40 Couldn't work on duplication, out sick. Will attempt to determine if problem can be replicated this weekend, if so I will reopen bug and coordinate schedule with you. fyi: no recurrence since all possible DIDs have been pointed to auto-attendant. Go ahead and close to get it out of the statistics for now. tim By: Mark Spencer (markster) 2004-06-11 09:16:23 Are you saying you only saw the problem when someone called a DID that was not in service? By: trmckee3 (trmckee3) 2004-06-12 12:39:52 That appears to be the problem. Call comes in on PRI to undefined extension, asterisk immediately hangs up the channel and the upstream provider sees the channel as free. Asterisk, however, appears in a zap show channels to see the channel as still in use and gets very confused when the D channels signals a new call on a channel it thinks is in use. Unfortunately, the DMS delivers calls from lowest numbered channel up, so a 'dead' channel 1 prevents any calls from coming in. This has not reoccurred since I created definitions for each possible DID. What is even stranger is that it didn't occur for days, then suddenly started to occur 2-4x/day. Calls were coming into the undefined DIDs all that time. There were no code updates or config changes to precipitate the problem. Insofar as I know the CLEC did not have any DMS updates at the time - I used to work for them and they would have told me. tim By: dalabera (dalabera) 2004-06-14 10:41:35 I have the same problem. Here is the output of my console: == Spawn extension (PAM, 1200, 1) exited non-zero on 'Zap/3-1' -- Hungup 'Zap/3-1' Jun 14 10:24:50 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:24:50 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. -- Nobody picked up in 15000 ms -- Executing VoiceMail2("SIP/1216-8f98", "u1201") in new stack -- Playing 'voicemail/default/1201/unavail' (language 'en') == Spawn extension (default, 1201, 2) exited non-zero on 'SIP/1216-8f98' == Spawn extension (default, 1201, 1) exited non-zero on 'Zap/4-1' -- Hungup 'Zap/4-1' Jun 14 10:25:10 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:11 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:12 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:13 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:15 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:15 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:19 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:20 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. -- Stopped music on hold on Zap/1-1 -- Started music on hold, class 'default', on Zap/1-1 Jun 14 10:25:23 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:24 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. -- Stopped music on hold on Zap/1-1 == Spawn extension (default, 1201, 0) exited non-zero on 'Zap/1-1' -- Executing Dial("Zap/1-1", "SIP/1201|15|t") in new stack -- Called 1201 -- SIP/1201-5d00 is ringing -- SIP/1201-5d00 answered Zap/1-1 Jun 14 10:25:30 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:30 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:36 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:37 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:41 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:25:42 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. pmrlinux01*CLI> show channels Channel (Context Extension Pri ) State Appl. Data SIP/1201-5d00 (default 1 ) Up Bridged Call Zap/1-1 Zap/1-1 (default 1201 1 ) Up Dial SIP/1201| SIP/1207-d317 (default 1 ) Up Bridged Call Zap/2-1 Zap/2-1 (PAM 1200 1 ) Up Queue ACD_PAM|T 4 active channel(s) Jun 14 10:26:11 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:26:11 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. pmrlinux01*CLI> zap show channel 1 Channel: 1*CLI> File Descriptor: 16 Span: 1 Extension: 5977600 Context: default Caller ID string: 3057170200 Destroy: 0 Signalling Type: PRI Signalling Owner: Zap/1-1 Real: Zap/1-1 Callwait: <None> Threeway: <None> Confno: -1 Propagated Conference: -1 Real in conference: 0 DSP: yes Relax DTMF: no Dialing/CallwaitCAS: 0/0 Default law: ulaw Fax Handled: no Pulse phone: no Echo Cancellation: 128 taps, currently ON PRI Flags: Call Actual Confinfo: Num/0, Mode/0x0000 Actual Confmute: No Jun 14 10:27:14 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. Jun 14 10:27:15 WARNING[1167272128]: chan_zap.c:6276 pri_dchannel: Ring request. pmrlinux01*CLI> By: trmckee3 (trmckee3) 2004-06-15 15:42:42 bug 1848 appears to display one of the same end-problems, a pri channel that asterisk thinks is in use but isn't. I'm still trying to schedule a time when I can try to force the problem to recurr. By: Paul Cadach (pcadach) 2004-06-15 21:29:19 Please, update libpri to the latest CVS head and enable pri intense debug to see which messages walks through the link when this situation is happens. I had this situation when something (I don't remember what exactly) was mis-configured, and error appeared with subsequent exchange with STATUS messages between Asterisk and PSTN. Yes, I remember - there was mistake about sending CALL PROCEEDING (and ALERTING?) on outgoing calls which is fixed about a month ago. Possible, we need to re-produce this situation and fix STATUS processing to make state machine to work synchronously with PSTN. By: trmckee3 (trmckee3) 2004-06-15 21:47:10 I will hopefully be able to attempt to reproduce the problem within a few days. I only have 1 PRI into my 24 hour NOCC and potentially taking it down raises a lot of eyebrows. By: Mark Spencer (markster) 2004-06-15 22:20:23 This is not a call processing problem. Asterisk is "doing the right thing" in terms of the state machine, but what's wrong is that there is somehow a channel that is associated with the subchannel, and it's not getting cleared (and the softhangup on it isn't fixing it). I MUST HAVE GDB ACCESS TO A MACHINE WITH THIS PROBLEM TO DIAGNOSE IT AND IT MUST BE STUCK IN THE STATE, OTHERWISE I CANNOT DO ANYTHING. I'm not sure how much more clearly I can put this. By: Paul Cadach (pcadach) 2004-06-16 00:18:53 Problem with non-existing extension at DID is not reproducible by me. Asterisk's version at working system is CVS-HEAD-05/22/04-16:30:48 with some non-critical changes which already on CVS. By: trmckee3 (trmckee3) 2004-06-16 08:11:04 I plan to see if I can reproduce the problem. If I can reliably reproduce it I'll schedule a time with you for debugging. I'd rather make efficient use of your time by being reasonably sure I can force the bug to occur on demand. By: Mark Spencer (markster) 2004-06-17 01:07:03 Please update tomorrow morning. I found some very serious difficiencies in the locking when running PRI tonight. By: trmckee3 (trmckee3) 2004-06-17 09:30:14 updating now. By: trmckee3 (trmckee3) 2004-06-17 21:39:04 update mid-day today. One important change, random dropping of inbound calls on the PRI seemed to stop. We had been encountering a significant number of them, but could never isolate it enough to file a report. hope to test the invalid extension trigger this weekend. By: Malcolm Davenport (mdavenport) 2004-06-21 13:18:15 Any news? By: trmckee3 (trmckee3) 2004-06-22 08:08:41 No, I had to do a major system firmware upgrade this weekend and ran into more problems than expected with it. I will try to get an evening later this week after the lingering problems are disposed of. By: Mark Spencer (markster) 2004-06-26 15:43:44 Assuming this has been fixed. If not feel free to reopen. |