[Home]

Summary:ASTERISK-06847: Linksys/Sipura 941 does not ring on inbound ZAP call
Reporter:Steven Andrews (sandrews13)Labels:
Date Opened:2006-04-25 14:09:56Date Closed:2006-05-17 11:23:58
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:SIP to SIP calls on Linksys 941 work normally; calls inbound from ZAP to 941 do not ring; however, if you remove phone line from the TDM (or x100p), begin the call, and then insert it after it's begun rining; the 941s will ring normally.  In this test, we're using a call group and included a BT-101 as extension 209.  The 941s are 205 and 206.  The BT-101 always works normally.  Under Additional Information, I'll include the CLI of the WORKING (phone line unplugged until call starts ringing) and the FAILED (phone line plugged in before call begins).

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

***WORKING***
Apr 25 14:09:23 DEBUG[3356] dsp.c: dsp busy pattern set to 0,0
Apr 25 14:09:23 VERBOSE[3472] logger.c: -- Starting simple switch on 'Zap/1-1'
Apr 25 14:09:27 NOTICE[3472] chan_zap.c: Got event 18 (Ring Begin)...
Apr 25 14:09:29 NOTICE[3472] chan_zap.c: Got event 2 (Ring/Answered)...
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetVar("Zap/1-1", "FROM_DID=s") in new stack
Apr 25 14:09:29 WARNING[3472] pbx.c: SetVar is deprecated, please use Set instead.
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetVar("Zap/1-1", "FAX_RX=disabled") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing Goto("Zap/1-1", "ext-group|1|1") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Goto (ext-group,1,1)
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing Macro("Zap/1-1", "rg-group|ringall|15||205-206-209") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing Macro("Zap/1-1", "user-callerid") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing DBget("Zap/1-1", "AMPUSER=DEVICE//user") in new stack
Apr 25 14:09:29 WARNING[3472] app_db.c: This application has been deprecated, please use the ${DB(family/key)} function instead.
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- DBget: varname=AMPUSER, family=DEVICE, key=/user
Apr 25 14:09:29 DEBUG[3472] db.c: Unable to find key '/user' in family 'DEVICE'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- DBget: Value not found in database.
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing DBget("Zap/1-1", "AMPUSERCIDNAME=AMPUSER//cidname") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- DBget: varname=AMPUSERCIDNAME, family=AMPUSER, key=/cidname
Apr 25 14:09:29 DEBUG[3472] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- DBget: Value not found in database.
Apr 25 14:09:29 DEBUG[3472] pbx.c: Expression result is '1'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing GotoIf("Zap/1-1", "1?5") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Goto (macro-user-callerid,s,5)
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing NoOp("Zap/1-1", "Using CallerID ") in new stack
Apr 25 14:09:29 DEBUG[3472] pbx.c: Function result is '0'
Apr 25 14:09:29 WARNING[3472] ast_expr2.fl: ast_yyerror(): syntax error: syntax error, unexpected TOK_NE, expecting TOK_MINUS or TOK_COMPL or TOK_LP or TOKEN; Input:
!=
^
Apr 25 14:09:29 WARNING[3472] ast_expr2.fl: If you have questions, please refer to doc/README.variables in the asterisk source.
Apr 25 14:09:29 DEBUG[3472] pbx.c: Expression result is '0'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing GotoIf("Zap/1-1", "0?4:3") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Goto (macro-rg-group,s,3)
Apr 25 14:09:29 DEBUG[3472] pbx.c: Function result is '0'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetCIDName("Zap/1-1", "") in new stack
Apr 25 14:09:29 WARNING[3472] app_setcidname.c: SetCIDName is deprecated, please use Set(CALLERID(name)=value) instead.
Apr 25 14:09:29 ERROR[3472] app_setcidname.c: SetCIDName requires an argument!
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetVar("Zap/1-1", "RGPREFIX=") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetCIDName("Zap/1-1", "") in new stack
Apr 25 14:09:29 ERROR[3472] app_setcidname.c: SetCIDName requires an argument!
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetVar("Zap/1-1", "RecordMethod=Group") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing Macro("Zap/1-1", "record-enable|1|Group") in new stack
Apr 25 14:09:29 DEBUG[3472] pbx.c: Function result is '0'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing GotoIf("Zap/1-1", "0 > 0?2:4") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Goto (macro-record-enable,s,4)
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing AGI("Zap/1-1", "recordingcheck|20060425-140929|1145988563.0") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- AGI Script recordingcheck completed, returning 0
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing NoOp("Zap/1-1", "No recording needed") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing SetVar("Zap/1-1", "RingGroupMethod=ringall") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing Macro("Zap/1-1", "dial|15|tr|205-206-209") in new stack
Apr 25 14:09:29 DEBUG[3472] pbx.c: Expression result is '1'
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing GotoIf("Zap/1-1", "1?4:2") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Goto (macro-dial,s,4)
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Executing AGI("Zap/1-1", "dialparties.agi") in new stack
Apr 25 14:09:29 VERBOSE[3472] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: priority = 4
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: callingani2 = 0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: accountcode =
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: channel = Zap/1-1
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: callerid = unknown
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: context = macro-dial
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: callington = 0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: dnid = unknown
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: request = dialparties.agi
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: calleridname = unknown
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: extension = s
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: language = en
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: uniqueid = 1145988563.0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: callingpres = 0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: type = Zap
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: rdnis = unknown
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: callingtns = 0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: enhanced = 0.0
Apr 25 14:09:30 VERBOSE[3472] logger.c: dialparties.agi: Caller ID is not set
Apr 25 14:09:30 VERBOSE[3472] logger.c: dialparties.agi: Methodology of ring is 'ringall'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 205 to extension map
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 206 to extension map
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 209 to extension map
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 205 to extension map
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 206 to extension map
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Added extension 209 to extension map
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '205' in family 'CF'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 205 cf is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '209' in family 'CF'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 209 cf is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '206' in family 'CF'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 206 cf is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '205' in family 'DND'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 205 do not disturb is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '209' in family 'DND'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 209 do not disturb is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '206' in family 'DND'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Extension 206 do not disturb is disabled
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '205' in family 'CW'
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '205' in family 'CFB'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 205
Apr 25 14:09:30 DEBUG[3476] manager.c: Manager received command 'Login'
Apr 25 14:09:30 VERBOSE[3476] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:30 VERBOSE[3476] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:30 VERBOSE[3476] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:30 VERBOSE[3476] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:30 WARNING[3476] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:30 DEBUG[3476] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3476] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3476] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:30 DEBUG[3476] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:30 VERBOSE[3476] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:30 DEBUG[3476] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:30 DEBUG[3476] manager.c: Manager received command 'Logoff'
Apr 25 14:09:30 VERBOSE[3476] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: dialparties.agi: Extension 205 is available...skipping checks
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '205' in family 'CALLTRACE'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: DbDel CALLTRACE/205 - Caller ID is not defined
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '209' in family 'CW'
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '209' in family 'CFB'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 209
Apr 25 14:09:30 DEBUG[3477] manager.c: Manager received command 'Login'
Apr 25 14:09:30 VERBOSE[3477] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:30 VERBOSE[3477] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:30 VERBOSE[3477] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:30 VERBOSE[3477] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:30 WARNING[3477] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:30 DEBUG[3477] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3477] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3477] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:30 DEBUG[3477] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:30 VERBOSE[3477] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:30 DEBUG[3477] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:30 DEBUG[3477] manager.c: Manager received command 'Logoff'
Apr 25 14:09:30 VERBOSE[3477] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: dialparties.agi: Extension 209 is available...skipping checks
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '209' in family 'CALLTRACE'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: DbDel CALLTRACE/209 - Caller ID is not defined
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '206' in family 'CW'
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '206' in family 'CFB'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 206
Apr 25 14:09:30 DEBUG[3478] manager.c: Manager received command 'Login'
Apr 25 14:09:30 VERBOSE[3478] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:30 VERBOSE[3478] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:30 VERBOSE[3478] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:30 VERBOSE[3478] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:30 WARNING[3478] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:30 DEBUG[3478] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3478] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:30 DEBUG[3478] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:30 DEBUG[3478] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:30 VERBOSE[3478] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:30 DEBUG[3478] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:30 DEBUG[3478] manager.c: Manager received command 'Logoff'
Apr 25 14:09:30 VERBOSE[3478] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:30 VERBOSE[3472] logger.c: dialparties.agi: Extension 206 is available...skipping checks
Apr 25 14:09:30 DEBUG[3472] db.c: Unable to find key '206' in family 'CALLTRACE'
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- dialparties.agi: DbDel CALLTRACE/206 - Caller ID is not defined
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- AGI Script dialparties.agi completed, returning 0
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- Executing Dial("Zap/1-1", "SIP/205&SIP/209&SIP/206|15|tr") in new stack
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Outgoing Call for 205
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- Called 205
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Outgoing Call for 209
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- Called 209
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:30 DEBUG[3472] chan_sip.c: Outgoing Call for 206
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- Called 206
Apr 25 14:09:30 DEBUG[3472] chan_zap.c: Requested indication 3 on channel Zap/1-1
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '54cdb9160b4ad3d52da1983951459ccb@192.168.1.68' Request 102: Found
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '54cdb9160b4ad3d52da1983951459ccb@192.168.1.68' Request 102: Found
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- SIP/209-060c is ringing
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '27dbcfac4a528bd9764ed21f4973904f@192.168.1.68' Request 102: Found
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3c923a902d72fa063067d67f3d6eddf7@192.168.1.68' Request 102: Found
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3c923a902d72fa063067d67f3d6eddf7@192.168.1.68' Request 102: Found
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- SIP/206-0791 is ringing
Apr 25 14:09:30 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '27dbcfac4a528bd9764ed21f4973904f@192.168.1.68' Request 102: Found
Apr 25 14:09:30 VERBOSE[3472] logger.c: -- SIP/205-e1ec is ringing
Apr 25 14:09:33 DEBUG[3472] chan_zap.c: Exception on 17, channel 1
Apr 25 14:09:33 DEBUG[3472] chan_zap.c: Got event Ring Begin(18) on channel 1 (index 0)
Apr 25 14:09:33 DEBUG[3472] chan_zap.c: Exception on 17, channel 1
Apr 25 14:09:33 DEBUG[3472] chan_zap.c: Got event Ring/Answered(2) on channel 1 (index 0)
Apr 25 14:09:33 DEBUG[3472] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0

***FAILED***
Apr 25 14:09:52 DEBUG[3356] dsp.c: dsp busy pattern set to 0,0
Apr 25 14:09:52 VERBOSE[3486] logger.c: -- Starting simple switch on 'Zap/1-1'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetVar("Zap/1-1", "FROM_DID=s") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetVar("Zap/1-1", "FAX_RX=disabled") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing Goto("Zap/1-1", "ext-group|1|1") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Goto (ext-group,1,1)
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing Macro("Zap/1-1", "rg-group|ringall|15||205-206-209") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing Macro("Zap/1-1", "user-callerid") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing DBget("Zap/1-1", "AMPUSER=DEVICE/13175070342/user") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- DBget: varname=AMPUSER, family=DEVICE, key=13175070342/user
Apr 25 14:09:53 DEBUG[3486] db.c: Unable to find key '13175070342/user' in family 'DEVICE'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- DBget: Value not found in database.
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing DBget("Zap/1-1", "AMPUSERCIDNAME=AMPUSER//cidname") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- DBget: varname=AMPUSERCIDNAME, family=AMPUSER, key=/cidname
Apr 25 14:09:53 DEBUG[3486] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- DBget: Value not found in database.
Apr 25 14:09:53 DEBUG[3486] pbx.c: Expression result is '1'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing GotoIf("Zap/1-1", "1?5") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Goto (macro-user-callerid,s,5)
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing NoOp("Zap/1-1", "Using CallerID ""PCS Phone I" <13175070342>") in new stack
Apr 25 14:09:53 DEBUG[3486] pbx.c: Function result is '0'
Apr 25 14:09:53 WARNING[3486] ast_expr2.fl: ast_yyerror(): syntax error: syntax error, unexpected TOK_NE, expecting TOK_MINUS or TOK_COMPL or TOK_LP or TOKEN; Input:
!=
^
Apr 25 14:09:53 WARNING[3486] ast_expr2.fl: If you have questions, please refer to doc/README.variables in the asterisk source.
Apr 25 14:09:53 DEBUG[3486] pbx.c: Expression result is '0'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing GotoIf("Zap/1-1", "0?4:3") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Goto (macro-rg-group,s,3)
Apr 25 14:09:53 DEBUG[3486] pbx.c: Function result is '0'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetCIDName("Zap/1-1", ""PCS Phone I") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetVar("Zap/1-1", "RGPREFIX=") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetCIDName("Zap/1-1", ""PCS Phone I") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing SetVar("Zap/1-1", "RecordMethod=Group") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing Macro("Zap/1-1", "record-enable|1|Group") in new stack
Apr 25 14:09:53 DEBUG[3486] pbx.c: Function result is '0'
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing GotoIf("Zap/1-1", "0 > 0?2:4") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Goto (macro-record-enable,s,4)
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing AGI("Zap/1-1", "recordingcheck|20060425-140953|1145988592.4") in new stack
Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- AGI Script recordingcheck completed, returning 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing NoOp("Zap/1-1", "No recording needed") in new stack
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing SetVar("Zap/1-1", "RingGroupMethod=ringall") in new stack
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing Macro("Zap/1-1", "dial|15|tr|205-206-209") in new stack
Apr 25 14:09:54 DEBUG[3486] pbx.c: Expression result is '1'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing GotoIf("Zap/1-1", "1?4:2") in new stack
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Goto (macro-dial,s,4)
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing AGI("Zap/1-1", "dialparties.agi") in new stack
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: priority = 4
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: callingani2 = 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: accountcode =
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: channel = Zap/1-1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: callerid = 13175070342
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: context = macro-dial
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: callington = 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: dnid = unknown
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: request = dialparties.agi
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: calleridname = PCS
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: extension = s
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: language = en
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: uniqueid = 1145988592.4
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: callingpres = 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: type = Zap
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: rdnis = unknown
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: callingtns = 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: enhanced = 0.0
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: Caller ID name and number are '13175070342'
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: Methodology of ring is 'ringall'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 205 to extension map
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 206 to extension map
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 209 to extension map
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 205 to extension map
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 206 to extension map
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Added extension 209 to extension map
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '205' in family 'CF'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 205 cf is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '209' in family 'CF'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 209 cf is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '206' in family 'CF'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 206 cf is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '205' in family 'DND'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 205 do not disturb is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '209' in family 'DND'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 209 do not disturb is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '206' in family 'DND'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Extension 206 do not disturb is disabled
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '205' in family 'CW'
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '205' in family 'CFB'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 205
Apr 25 14:09:54 DEBUG[3490] manager.c: Manager received command 'Login'
Apr 25 14:09:54 VERBOSE[3490] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:54 VERBOSE[3490] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:54 VERBOSE[3490] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:54 VERBOSE[3490] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:54 WARNING[3490] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:54 DEBUG[3490] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3490] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3490] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:54 DEBUG[3490] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:54 VERBOSE[3490] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:54 DEBUG[3490] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: Extension 205 is available...skipping checks
Apr 25 14:09:54 DEBUG[3490] manager.c: Manager received command 'Logoff'
Apr 25 14:09:54 VERBOSE[3490] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: DbSet CALLTRACE/205 to 13175070342
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '209' in family 'CW'
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '209' in family 'CFB'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 209
Apr 25 14:09:54 DEBUG[3491] manager.c: Manager received command 'Login'
Apr 25 14:09:54 VERBOSE[3491] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:54 VERBOSE[3491] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:54 VERBOSE[3491] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:54 VERBOSE[3491] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:54 WARNING[3491] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:54 DEBUG[3491] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3491] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3491] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:54 DEBUG[3491] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:54 VERBOSE[3491] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:54 DEBUG[3491] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: Extension 209 is available...skipping checks
Apr 25 14:09:54 DEBUG[3491] manager.c: Manager received command 'Logoff'
Apr 25 14:09:54 VERBOSE[3491] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: DbSet CALLTRACE/209 to 13175070342
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '206' in family 'CW'
Apr 25 14:09:54 DEBUG[3486] db.c: Unable to find key '206' in family 'CFB'
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 206
Apr 25 14:09:54 DEBUG[3492] manager.c: Manager received command 'Login'
Apr 25 14:09:54 VERBOSE[3492] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 25 14:09:54 VERBOSE[3492] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Apr 25 14:09:54 VERBOSE[3492] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 25 14:09:54 VERBOSE[3492] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Apr 25 14:09:54 WARNING[3492] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Apr 25 14:09:54 DEBUG[3492] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3492] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Apr 25 14:09:54 DEBUG[3492] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Apr 25 14:09:54 DEBUG[3492] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Apr 25 14:09:54 VERBOSE[3492] logger.c: == Manager 'admin' logged on from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS
Apr 25 14:09:54 DEBUG[3492] manager.c: Manager received command 'ExtensionState'
Apr 25 14:09:54 VERBOSE[3486] logger.c: dialparties.agi: Extension 206 is available...skipping checks
Apr 25 14:09:54 DEBUG[3492] manager.c: Manager received command 'Logoff'
Apr 25 14:09:54 VERBOSE[3492] logger.c: == Manager 'admin' logged off from 127.0.0.1
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- dialparties.agi: DbSet CALLTRACE/206 to 13175070342
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- AGI Script dialparties.agi completed, returning 0
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Executing Dial("Zap/1-1", "SIP/205&SIP/209&SIP/206|15|tr") in new stack
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Outgoing Call for 205
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Called 205
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Outgoing Call for 209
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Called 209
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Setting NAT on RTP to 0
Apr 25 14:09:54 DEBUG[3486] chan_sip.c: Outgoing Call for 206
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- Called 206
Apr 25 14:09:54 DEBUG[3486] chan_zap.c: Requested indication 3 on channel Zap/1-1
Apr 25 14:09:54 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7c13a386726275a63bd605f51fb8e7e2@192.168.1.68' Request 102: Found
Apr 25 14:09:54 DEBUG[3355] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7c13a386726275a63bd605f51fb8e7e2@192.168.1.68' Request 102: Found
Apr 25 14:09:54 VERBOSE[3486] logger.c: -- SIP/209-fda5 is ringing
Apr 25 14:09:56 DEBUG[3486] chan_zap.c: Exception on 17, channel 1
Apr 25 14:09:56 DEBUG[3486] chan_zap.c: Got event Ring Begin(18) on channel 1 (index 0)
Apr 25 14:09:58 DEBUG[3486] chan_zap.c: Exception on 17, channel 1
Apr 25 14:09:58 DEBUG[3486] chan_zap.c: Got event Ring/Answered(2) on channel 1 (index 0)
Apr 25 14:09:58 DEBUG[3486] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
Apr 25 14:10:02 DEBUG[3486] chan_zap.c: Exception on 17, channel 1
Apr 25 14:10:02 DEBUG[3486] chan_zap.c: Got event Ring Begin(18) on channel 1 (index 0)
Apr 25 14:10:03 DEBUG[3486] chan_zap.c: Exception on 17, channel 1
Apr 25 14:10:03 DEBUG[3486] chan_zap.c: Got event Ring/Answered(2) on channel 1 (index 0)
Apr 25 14:10:03 DEBUG[3486] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
Apr 25 14:10:10 VERBOSE[3486] logger.c: -- Nobody picked up in 15000 ms

Comments:By: Joshua C. Colp (jcolp) 2006-04-27 14:46:54

Okay... yeah...

Last debug block you pasted says one phone is ringing and the others are not. Are they behind NAT? and can you skim down the output a bit? I had to filter through a lot of useless AMP/FreePBX/whatever stuff to get to the real stuff.
By: Steven Andrews (sandrews13) 2006-04-27 14:55:54

None are behind NAT; this is all on the same LAN, same segment, no QOS.  209 is ringing, that's the BT-101 (noted that in the original notes) and is in the ring group as a control to eliminate the ring group as the fault.

Didn't think it was appropriate to cut out sections in the middle of a trace... If you think it'll help, I'll setup a ring in to one of these 941s direct from the ZAP channel; one unplugged from the ZAP before the call start, and one with the ZAP plugged in before the call starts; but the only thing that's going to cut out is anything to do with the ring groups, which isn't that much.
By: Steven Andrews (sandrews13) 2006-04-28 10:27:10

Further notes: I setup a freedigits.com SIP trunk; the inbound calls for this I have routing through the same IVR, call groups and these calls ring the 941 phones normally.
By: Serge Vecher (serge-v) 2006-05-09 13:01:09

well, if the phones work with a sip trunk, there is some sort of Zaptel issue. For support on Zaptel hardware, please contact Digium Technical Support at support@digium.com.

Thanks and good luck.
By: Steven Andrews (sandrews13) 2006-05-11 12:51:09

The rathole gets a little deeper...

Turns out the fault here is the caller ID info.  What I was manually doing is tweaking caller ID name info that gets picked up on ZAP or even SIP channels from an SPA-3000.  Caller ID was being transmitted with name info, and no closing quote so it shows up as ("PCS Phones      ) sans perens.  EX:

Apr 25 14:09:53 VERBOSE[3486] logger.c: -- Executing NoOp("Zap/1-1", "Using CallerID ""PCS Phone I" <13175070342>") in new stack

I added some code to chan_sip.c to stip quotes entirely on calls from asterisk to the 941s and then they worked fine.  Not my code, found here:
http://www.voip-info.org/wiki/view/D-link+DVG-1120

I suspect though this isn't the proper place for this code.  I'm de-mangling it from asterisk to the called phone and I think it should be where the call comes inbound to the system whether that be a zap, sip, etc since when I take the call inbound from an SPA-3000, asterisk will not answer it unless i pass the call immediately, forgoing the callerid info.
By: Serge Vecher (serge-v) 2006-05-11 13:16:03

can you please enable sip debug and run the call again, without your patch. Please include here as attachment.

thanks.
By: Steven Andrews (sandrews13) 2006-05-11 13:52:44

I've really hacked up this box, so I'll make a new one and do as you ask.  I got a snippet of code someone else used to cure the problem.

extensions.conf; added to [from-pstn]
exten => s,1,Set(CALLERID(name)=${CALLERID(name):1})

evidently it hacks off the first character.

the one thing i found in common with the guy that did this; we've both using vonage and are served off an ata-186.
By: Joshua C. Colp (jcolp) 2006-05-16 19:24:01

So basically what happened is that the callerid that came in caused a corrupted SIP invite which it freaked out on... okay, I'll buy that! Any merit in keeping the bug open or should we close it?
By: Steven Andrews (sandrews13) 2006-05-17 07:28:16

you tell me.  it appears so far that the caller ID coming from the ata-186 has an extra space between From and the beginning of the caller id data.  that causes * to think there's no quotes around the caller id name, when the next digit really is a quote.  the fix of hacking off the first char of caller ID seems to work for this situation.

it was my supposition that * is supposed to be loose in what it accepts but strict in what it sends and this doesn't seem to follow this; but if i'm off-base, call me on it please.  the ata-186 is end of life so i don't really want to stir up a nest here; but i don't recall this problem post 1.2.
By: Steven Andrews (sandrews13) 2006-05-17 07:28:34

sorry, i meant pre 1.2
By: Joshua C. Colp (jcolp) 2006-05-17 10:42:23

Out of curiosity what happens if you use pedantic? Does it go horrible bad, or work fine without any intervention?
By: Steven Andrews (sandrews13) 2006-05-17 11:21:17

isn't pedantic=yes for sip.conf?  how would that work for calls coming in on zap?
By: Joshua C. Colp (jcolp) 2006-05-17 11:23:57

Mental failure there, ignore me... hrm - okay... since we've narrowed down the issue, I'm going to close this issue but writing myself a note about more strict callerid stuff in the future. Thanks!