[Home]

Summary:ASTERISK-00089: Manager Events Don't Seem Right
Reporter:jayson (jayson)Labels:
Date Opened:2003-08-12 15:45:35Date Closed:2008-01-15 14:31:57.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) manager_fixes.patch
Description:When dialing another extension (say that rings another phone via a macro), the order of events is slightly off.  The first newchannel event is created long after the phone goes offhook (but the channel does appear in a Status!).  Then, the phone which is rung by the Dial command appears to log two newchannel events!

****** ADDITIONAL INFORMATION ******

Here goes to chain of events:

Pick up Zap/36.

<nothing>

Execute Action: Status at the point shows:

Action: Status

Response: Success
Message: Channel status will follow

Event: Status
Channel: Zap/36-1
CallerID: "Jayson" <(417)555-1212>
State: Down

Uniqueid: 1060719943.10

Hanging up DOES transmit a Hangup.

Event: Hangup
Channel: Zap/36-1
Uniqueid: 1060719388.8

Strange.

Next, ring Zap/29:

First we get a newchannel and a slew of newexten's as the system works through the macros:

Event: Newchannel
Channel: Zap/36-1
State: Ring
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060719103.6

Well, it's a bit late, but it's good that it showed up.  Next:

Event: Newexten
Channel: Zap/36-1
Context: outgoing
Extension: ASTERISK-102
Priority: 1
Uniqueid: 1060719103.6

Event: Newexten
Channel: Zap/36-1
Context: outgoing
Extension: ASTERISK-102
Priority: 2
Uniqueid: 1060719103.6

Event: Newexten
Channel: Zap/36-1
Context: std-exten
Extension: 106
Priority: 1
Uniqueid: 1060719103.6

That is now the Dial command with the correct Zap/29

Event: Newchannel
Channel: Zap/29-1
State: Rsrvd
Callerid: <unknown>
Uniqueid: 1060719104.7

What is this??

Event: Newchannel
Channel: Zap/29-1
State: Rsrvd
Callerid: "Kevin" <(417)555-1212>
Uniqueid: 1060719104.7

That makes more sense, although Rsrvd is a strange state to be in.  Does that come into play in DND?

Event: Newstate
Channel: Zap/29-1
State: Ringing
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060719104.7

Event: Newstate
Channel: Zap/36-1
State: Ringing
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060719103.6

Event: Hangup
Channel: Zap/29-1
Uniqueid: 1060719104.7

Event: Hangup
Channel: Zap/36-1
Uniqueid: 1060719103.6

Those make sense.

My concern is:

Two newchannel events is just wrong.
Hangup events on channels which never had a newchannel event don't make sense.
Status on a channel which had no newchannel event doesn't make sense.
Picking up the phone "SHOULD" generate a newchannel event noting State: Down.
Without this there is no sane way to know that status of a channel at certain critical points.  Since ZapTel actually knows about this, it appears to be a case of "one hand not knowing what the other is doing".
Comments:By: jayson (jayson) 2003-08-12 15:53:47

On the list of other oddities, Status responses seem completely botched.

Specifically, on requesting status with only one phone (Zap/29) off the hook then hang it up, I recieve this:

Response: Success
Message: Channel status will follow

Event: Status
Channel: Zap/36-1
CallerID: "Jayson" <(417)555-1212>
State: Down

Uniqueid: 1060720494.12
Event: Hangup
Channel: Zap/36-1
Uniqueid: 1060720494.12

Is it just me, or should this be:

Event: Status
Channel: Zap/36-1
CallerID: "Jayson" <(417)555-1212>
State: Down
Uniqueid: 1060720494.12

Event: Hangup
Channel: Zap/36-1
Uniqueid: 1060720494.12
By: jayson (jayson) 2003-08-12 16:03:04

Looks like I've found it.  There appears to be a swapped se of lines in the source.  Here's a cvs diff to fix it:

--snip--
# cvs diff -u2 manager.c
Index: manager.c
===================================================================
RCS file: /usr/cvsroot/asterisk/manager.c,v
retrieving revision 1.15
diff -u -2 -r1.15 manager.c
--- manager.c   4 Aug 2003 21:44:48 -0000       1.15
+++ manager.c   12 Aug 2003 21:08:19 -0000
@@ -341,6 +341,6 @@
                       "State: %s\r\n"
                       "%s"
-                       "\r\n"
-                       "Uniqueid: %s\r\n",
+                       "Uniqueid: %s\r\n"
+                       "\r\n",
                       c->name, c->callerid ? c->callerid : "<unknown>",
                       ast_state2str(c->_state), bridge, c->uniqueid);

--snip--

Patch, rinse, repeat.  Hope that helps.
By: jayson (jayson) 2003-08-12 16:55:41

I noticed that the Newchannel event can be generated from one of two places.  Either ast_setstate or ast_request in channel.c.  That made me think that, perhaps, ast_setstate is getting called before (or during) ast_request.

I hacked in a line for each generator that added the source as a header and, sure enough, got:

Event: Newchannel
Channel: Zap/29-1
Source: setstate
State: Rsrvd
Callerid: <unknown>
Uniqueid: 1060724053.1

Event: Newchannel
Channel: Zap/29-1
State: Rsrvd
Source: request
Callerid: "Kevin" <(417)555-1212>
Uniqueid: 1060724053.1

Currently attempting to track down where this gets called.

Can anybody explain the wisdom behind the logic in ast_setstate that determines when to generate Newchannel instead of Newstate (see channel.c line 2054)?
By: jayson (jayson) 2003-08-12 17:05:13

Guessing that my above two problems are to be remedied in chan_zap.c.

Looks like chan_zap does not:

1.  Set STATE_OFFHOOK when the phone goes offhook.
--and--
2.  Calls ast_setstate before the channel requestor (zt_new?) exits.

I'm currently don't think #2 is a problem.  Rather, it may be necessary to put the same logic in ast_request that is in ast_setstate (print out a Newchannel IFF last state is STATE_DOWN) otherwise print Newstate.
By: jayson (jayson) 2003-08-12 17:50:17

Okay.  Assuming STATE_OFFHOOK is correct for the period between when the phone is picked up and a call is dialed/rung/connected, I've added a line that sets that state (it may not be correct, as I don't understand the nonFX? signalling types to know).  Is this correct?

Next, I have confirmed ast_setstate is called from within the chan_zap channel creation function.  I have modified such that ast_setstate is the only place that generated Newchannel.  I think this should be okay.  There are two scenarios:

1.  Some mythical channel type executes completely through ast_request without triggering ast_setstate (thus not issueing a Newchannel event)

I think this is not a problem because, with the initial state being AST_STATE_DOWN, any change of state at all will cause this to be kicked out.  I cannot envision any time when we will request a channel, then not change state.  If such a time were to arrive, I can't imagine that we SHOULD generate a Newchannel event as I suspect a Hangup event won't be generated either (what does Hangup mean on a Down channel?).

2.  ast_setstate is called, thereby generating the correct Newchannel event.

Is this correct or have I missed something?

Patches ensue:

First for the extraneous Newchannel event
--snip--
# cvs diff -u2 channel.c
Index: channel.c
===================================================================
RCS file: /usr/cvsroot/asterisk/channel.c,v
retrieving revision 1.33
diff -u -2 -r1.33 channel.c
--- channel.c   11 Aug 2003 22:17:46 -0000      1.33
+++ channel.c   12 Aug 2003 22:53:55 -0000
@@ -1553,5 +1553,6 @@
                       if (chan->requester)
                               c = chan->requester(type, capabilities, data);
-                       if (c) {
+                       /* ast_setstate should generate this when appropriate*/
+/*                     if (c) {
//                             ast_device_state_changed(c->name);
                               manager_event(EVENT_FLAG_CALL, "Newchannel",
@@ -1561,5 +1562,5 @@
                               "Uniqueid: %s\r\n",
                               c->name, ast_state2str(c->_state), c->callerid ? c->callerid : "<unknown>", c->uniqueid);
-                       }
+                       }*/
                       return c;
               }
--snip--

Next for the OFFHOOK message:

--snip--
# cvs diff -u2 channels/chan_zap.c
Index: channels/chan_zap.c
===================================================================
RCS file: /usr/cvsroot/asterisk/channels/chan_zap.c,v
retrieving revision 1.77
diff -u -2 -r1.77 chan_zap.c
--- channels/chan_zap.c 8 Aug 2003 04:20:54 -0000       1.77
+++ channels/chan_zap.c 12 Aug 2003 22:56:34 -0000
@@ -3741,4 +3741,5 @@
       if (p->dsp)
               ast_dsp_digitreset(p->dsp);
+       ast_setstate(chan,AST_STATE_OFFHOOK); /* FIXME:  Put back onhook for errors */
       switch(p->sig) {
       case SIG_FEATD:
--snip--
By: jayson (jayson) 2003-08-12 17:52:49

Mmmm.  Looks like Mantis ate those patches.  Here's an attachement.
By: Mark Spencer (markster) 2003-08-14 23:30:32

Tell me if you like this better.
By: jayson (jayson) 2003-08-15 12:30:33

Mmmmm.  It doesn't appear to work.  At first glance it is fine (Rsrvd State on Offhook).   However, when I dial an extension/ring another phone, it's not correct on their end.  Examine the following transcript:

Event: Newchannel
Channel: Zap/36-1
State: Rsrvd
Callerid: <unknown>
Uniqueid: 1060963051.3

Event: Newstate
Channel: Zap/36-1
State: Ring
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060963051.3

Event: Newexten
Channel: Zap/36-1
Context: outgoing
Extension: ASTERISK-102
Priority: 1
Uniqueid: 1060963051.3

Event: Newexten
Channel: Zap/36-1
Context: outgoing
Extension: ASTERISK-102
Priority: 2
Uniqueid: 1060963051.3

Event: Newexten
Channel: Zap/36-1
Context: std-exten
Extension: 106
Priority: 1
Uniqueid: 1060963051.3

Event: Newchannel
Channel: Zap/29-1
State: Rsrvd
Callerid: <unknown>
Uniqueid: 1060963054.4

Event: Newchannel
Channel: Zap/29-1
State: Rsrvd
Callerid: "Kevin" <(417)555-1212>
Uniqueid: 1060963054.4

Event: Newstate
Channel: Zap/29-1
State: Ringing
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060963054.4

Event: Newstate
Channel: Zap/36-1
State: Ringing
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060963051.3

Event: Newstate
Channel: Zap/29-1
State: Up
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060963054.4

Event: Newstate
Channel: Zap/36-1
State: Up
Callerid: "Jayson" <(417)555-1212>
Uniqueid: 1060963051.3

Event: Link
Channel1: Zap/36-1
Channel2: Zap/29-1

Event: Unlink
Channel1: Zap/36-1
Channel2: Zap/29-1

Event: Hangup
Channel: Zap/29-1
Uniqueid: 1060963054.4

Event: Hangup
Channel: Zap/36-1
Uniqueid: 1060963051.3

--

Simplified, that becomes:

A:  Newchannel, Rsrvd
A:  Newstate, Ring
A:  Newexten, ASTERISK-102,1@outgoing
A:  Newexten, ASTERISK-102,2@outgoing
A:  Newexten, 106,1@std-exten
B:  Newchannel, Rsrvd (ast_setstate setting during channel init)
B:  Newchannel, Rsrvd (ast_request message)
B:  Newstate, Ringing
A:  Newstate, Ringing
B:  Newstate, Up
A:  Newstate, Up
Link:  A<->B
Unlink: A<->B
B:  Hangup
A:  Hangup

Notice the two Newchannel events?
As long as calling ast_setstate can generate a newchannel AND ast_request can generate a newchannel, we will have this problem.  This effectively requires every channel driver to *CORRECTLY* handle state setting at a low level.

The only solutions I see are:

a)  make setstate generate the event
b)  attach a state variable to channel to keep track of whether a newchannel has been generated
c)  create a manager event queue and use a consumer/producer model to generate events

Advantages:
a)  Only generate event in one place.  Big win.
a)  Less special case code.
b)  Less modification of code.
c)  Allows the ast_request function to grab event and modify it (prevents newchannel followed immediately by setstate)
c)  Scales well to large numbers of channels

Disadvantages:
a)  Slightly invasive.
a)  ast_request is probably the "correct" place to make the message
b)  Requires modules to correctly handle state backend.
b)  Makes special hooks to set_state more invasive
b)  Easy to make mistakes in module design can break event management (ie.  internal driver breakage breaks external interface)
c)  Probably over-engineering
c)  Bad performance on queue handling (fixing-up the event requires search or traversal of entire queue, bad performance in the general case of no spurious event).

I'd recommend just putting it in setstate for simplicity.  Currently the set_state function already uses ._state == AST_STATE_DOWN to know to generate Newchannel--but ast_request doesn't (that's the heart of this problem).  Since ast_request is going to initially set a state SOMEWHERE, it makes sense to me just to take the Newchannel event out of ast_request and generate it from ast_setstate (which MUST be called somewhere, right?).  Neat, tidy, without incident.

Hope that helps (even if it is a tad exhaustive in the explanation department).

Jayson
By: Mark Spencer (markster) 2003-08-15 13:23:07

I think the concern is pedantic but I've made the change anyway.  Confirm it's okay with you.
By: jayson (jayson) 2003-08-15 16:08:57

I am probably overly pedantic in general (I do apologize).

Looks like it works now.  Thanks for the fix.
By: Digium Subversion (svnbot) 2008-01-15 14:31:57.000-0600

Repository: asterisk
Revision: 1338

U   trunk/apps/app_agi.c
U   trunk/apps/app_enumlookup.c
U   trunk/apps/app_festival.c
U   trunk/apps/app_queue.c
U   trunk/apps/app_voicemail2.c
U   trunk/channels/chan_sip.c
U   trunk/channels/chan_zap.c
U   trunk/codecs/ilbc/FrameClassify.c
U   trunk/codecs/ilbc/LPCdecode.c
U   trunk/codecs/ilbc/LPCencode.c
U   trunk/codecs/ilbc/StateConstructW.c
U   trunk/codecs/ilbc/StateSearchW.c
U   trunk/codecs/ilbc/anaFilter.c
U   trunk/codecs/ilbc/createCB.c
U   trunk/codecs/ilbc/doCPLC.c
U   trunk/codecs/ilbc/enhancer.c
U   trunk/codecs/ilbc/filter.c
U   trunk/codecs/ilbc/gainquant.c
U   trunk/codecs/ilbc/getCBvec.c
U   trunk/codecs/ilbc/helpfun.c
U   trunk/codecs/ilbc/hpInput.c
U   trunk/codecs/ilbc/hpOutput.c
U   trunk/codecs/ilbc/iCBConstruct.c
U   trunk/codecs/ilbc/iCBSearch.c
U   trunk/codecs/ilbc/iLBC_decode.c
U   trunk/codecs/ilbc/iLBC_encode.c
U   trunk/codecs/ilbc/lsf.c
U   trunk/codecs/ilbc/packing.c
U   trunk/codecs/ilbc/syntFilter.c
U   trunk/pbx/pbx_gtkconsole.c

------------------------------------------------------------------------
r1338 | markster | 2008-01-15 14:31:57 -0600 (Tue, 15 Jan 2008) | 8 lines

Asterisk:
ASTERISK-68 - Should eliminate probs on VMWI
ASTERISK-37 - Dynamic add survives reload
ASTERISK-69 - Make festival honor its arguments
ASTERISK-89 - Make events on FXO interfaces more logical
ASTERISK-22 - Prefer "bindaddr" to logical address for registrations
??? - Record crashes AGI

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=1338