| Summary: | ASTERISK-11108: Get "No such channel" when querring variable | ||
| Reporter: | Pascal Lambert (pascallambert) | Labels: | |
| Date Opened: | 2007-12-24 10:57:04.000-0600 | Date Closed: | 2007-12-27 12:25:02.000-0600 |
| Priority: | Major | Regression? | No |
| Status: | Closed/Complete | Components: | Core/ManagerInterface |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ||
| Description: | Our application depends on the manager to report the call progression. Unfortunately in more than 50% of the time we get an invalid result from the manager API but only on one of the 2 asterisk server I'm testing my code. Both are with the same version of asterisk. I'm doing my testing originating to soft SIP phone. The whole story now; We use Local channel to originate call. Local channel will create child channel. The manager API will reported back each child channel created. Unfortunately the Local channel driver doesn't related those child channel to the initial parent. So we need to bind a variable to each originating call and when we received notification of a new channel we immediately query back the value of our variable in order to related it with the originating call. Then problem is sometime we get a "No such channel" error in our response for the "GetVar" call (see the log below). I've no clue has why we get this, especially that it worked on one server and not the other one again both with the same version. Any help as to what take a look at will be greatly appreciate. ****** ADDITIONAL INFORMATION ****** This is what we received/send by the manager API 2007-12-24 08:14:32,251 DEBUG [main]: -->Send: action: Originate actionid: 12258573_19#AJ_ORIGINATE_2 timeout: 60000 exten: s async: true variable: __AJ_TRACE_ID=AJ_ORIGINATE_2 context: ExecAGIApp priority: 1 channel: Local/101@internal 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_19#AJ_ORIGINATE_2 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Message: Originate successfully queued 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-ee1e,1 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Down 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.124 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_20# variable: AJ_TRACE_ID channel: Local/101@internal-ee1e,1 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-ee1e,2 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Ring 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.125 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: (null) 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_20# 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_21# variable: AJ_TRACE_ID channel: Local/101@internal-ee1e,2 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Error 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_21# 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Message: No such channel 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newcallerid 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-ee1e,1 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: <Unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <Unknown> 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.124 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CID-CallingPres: 0 (Presentation Allowed, Not Screened) 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newexten 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-ee1e,2 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Context: internal 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Extension: 101 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Priority: 1 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Application: Macro 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: AppData: pascal-dial|SIP/pascal 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.125 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newexten 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-ee1e,2 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Context: macro-pascal-dial 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Extension: s 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Priority: 1 2007-12-24 08:14:32,251 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Application: Dial 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: AppData: SIP/pascal|50 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.125 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-09bfafb0 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Down 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.126 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_22# variable: AJ_TRACE_ID channel: SIP/pascal-09bfafb0 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Error 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_22# 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Message: No such channel 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Dial 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Source: Local/101@internal-ee1e,2 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Destination: SIP/pascal-09bfafb0 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: <unknown> 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: SrcUniqueID: 1198509115.125 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: DestUniqueID: 1198509115.126 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_23# variable: AJ_TRACE_ID channel: Local/101@internal-ee1e,2 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: AJ_ORIGINATE_2 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_23# 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newcallerid 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-09bfafb0 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: 101 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_24# variable: AJ_TRACE_ID channel: SIP/pascal-09bfafb0 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <Unknown> 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.126 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CID-CallingPres: 0 (Presentation Allowed, Not Screened) 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: AJ_ORIGINATE_2 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_24# 2007-12-24 08:14:32,266 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newstate 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-09bfafb0 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Ringing 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: 101 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198509115.126 2007-12-24 08:14:32,360 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: | ||
| Comments: | By: Pascal Lambert (pascallambert) 2007-12-24 11:43:34.000-0600 Interesting thing to note, if I delay the GetVar call of 100ms I don't see the problem anymore which could explain why I don't see the problem on my second server has it's less powerful then the first one. By: Tilghman Lesher (tilghman) 2007-12-24 12:08:08.000-0600 Okay, so it seems that you've found the solution... just delay the query for a period of time, because the notification occurs before the channel is fully created. By: Pascal Lambert (pascallambert) 2007-12-24 12:15:02.000-0600 Come on!!! Delay 100ms is not a fix. That's a cheap patch. You can't ask everybody that get that problem to delay there stuff of a certain amount of time. That's not reliable. Delay it is just a lead to the root of the problem. If I received a notification from the manager that a channel is created I MUST be able to query it at anytime. Plus this 100ms is working here on my server might be something else for someone else. I don't want to be annoying here but please don't tell me the issue is fix. By: Digium Subversion (svnbot) 2007-12-24 13:33:38.000-0600 Repository: asterisk Revision: 94767 U branches/1.4/main/channel.c ------------------------------------------------------------------------ r94767 | tilghman | 2007-12-24 13:33:37 -0600 (Mon, 24 Dec 2007) | 5 lines Race: we need to wait to queue a NewChannel event until after the channel is inserted into the channel list. The reason is because some manager users immediately queue requests from the channel when they see that event and are confused when Asterisk reports no such channel. (Closes issue ASTERISK-11108) ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=94767 By: Digium Subversion (svnbot) 2007-12-24 13:40:15.000-0600 Repository: asterisk Revision: 94768 _U trunk/ U trunk/main/channel.c ------------------------------------------------------------------------ r94768 | tilghman | 2007-12-24 13:40:14 -0600 (Mon, 24 Dec 2007) | 13 lines Merged revisions 94767 via svnmerge from https://origsvn.digium.com/svn/asterisk/branches/1.4 ........ r94767 | tilghman | 2007-12-24 13:36:59 -0600 (Mon, 24 Dec 2007) | 5 lines Race: we need to wait to queue a NewChannel event until after the channel is inserted into the channel list. The reason is because some manager users immediately queue requests from the channel when they see that event and are confused when Asterisk reports no such channel. (Closes issue ASTERISK-11108) ........ ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=94768 By: Pascal Lambert (pascallambert) 2007-12-27 10:20:09.000-0600 Almost there ;) I've apply the patch and I don't see the error anymore but GetVar return sometime (null). see ActionID 12258573_32 vs 12258573_35. And again if I delay the query a few millisecond I always get the proper behavior. By the way thank you for the first SUPER FAST reply/fix :) Note also that before applying the patch I was experiencing the same also I just didn't mentioned it. ------------ trace of manager ------------- actionid: 12258573_31#AJ_ORIGINATE_4 timeout: 60000 exten: s async: true variable: __AJ_TRACE_ID=AJ_ORIGINATE_4 context: internal priority: 1 channel: Local/101@internal 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_31#AJ_ORIGINATE_4 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Message: Originate successfully queued 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-5421,1 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Down 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.66 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_32# variable: AJ_TRACE_ID channel: Local/101@internal-5421,1 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-5421,2 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Ring 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.67 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: (null) 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_32# 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_33# variable: AJ_TRACE_ID channel: Local/101@internal-5421,2 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newcallerid 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-5421,1 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: <Unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <Unknown> 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.66 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CID-CallingPres: 0 (Presentation Allowed, Not Screened) 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: (null) 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_33# 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newexten 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-5421,2 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Context: internal 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Extension: 101 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Priority: 1 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Application: Macro 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: AppData: pascal-dial|SIP/pascal 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.67 2007-12-27 09:02:16,936 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newexten 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: Local/101@internal-5421,2 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Context: macro-pascal-dial 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Extension: s 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Priority: 1 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Application: Dial 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: AppData: SIP/pascal|50 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.67 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newchannel 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-08b4ced0 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Down 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDNum: <unknown> 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.68 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_34# variable: AJ_TRACE_ID channel: SIP/pascal-08b4ced0 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: (null) 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_34# 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Dial 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Source: Local/101@internal-5421,2 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Destination: SIP/pascal-08b4ced0 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: <unknown> 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: SrcUniqueID: 1198771171.67 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: DestUniqueID: 1198771171.68 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_35# variable: AJ_TRACE_ID channel: Local/101@internal-5421,2 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: AJ_ORIGINATE_4 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_35# 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newcallerid 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-08b4ced0 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: 101 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <Unknown> 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.68 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CID-CallingPres: 0 (Presentation Allowed, Not Screened) 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java DaemonPool-2-thread-1]: -->Send: action: GetVar actionid: 12258573_36# variable: AJ_TRACE_ID channel: SIP/pascal-08b4ced0 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Response: Success 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Variable: AJ_TRACE_ID 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Value: AJ_ORIGINATE_4 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: ActionID: 12258573_36# 2007-12-27 09:02:16,952 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Event: Newstate 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Privilege: call,all 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Channel: SIP/pascal-08b4ced0 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: State: Ringing 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerID: 101 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: CallerIDName: <unknown> 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: Uniqueid: 1198771171.68 2007-12-27 09:02:17,046 DEBUG [Asterisk-Java ManagerConnection-0-Reader-0]: <--Recv: By: Tilghman Lesher (tilghman) 2007-12-27 11:48:23.000-0600 Are you setting the variable in sip.conf or in the dialplan? By: Pascal Lambert (pascallambert) 2007-12-27 12:13:23.000-0600 Dynamically when invoking the Originate action: http://www.voip-info.org/wiki/index.php?page=Asterisk+Manager+API+Action+Originate variable : __AJ_TRACE_ID ------------ trace of manager ------------- 2007-12-27 09:02:16,936 DEBUG [main]: -->Send: action: Originate actionid: 12258573_31#AJ_ORIGINATE_4 timeout: 60000 exten: s async: true variable: __AJ_TRACE_ID=AJ_ORIGINATE_4 context: internal priority: 1 channel: Local/101@internal By: Tilghman Lesher (tilghman) 2007-12-27 12:25:02.000-0600 Yeah, sorry, can't solve that. The variable is getting set AFTER the channel is created, and you simply raced to access the channel before the variable was created. Add a delay, noting that the variable isn't populated immediately upon channel creation, and you have your fix. | ||