Two phones produce different results but it all looks

Good morning asterizites:

– Executing Dial(“SIP/501-08e8a468”, “Zap/4/18884500650”) in new stack
– Called 4/18884500650
– Zap/4-1 is ringing
– Hungup ‘Zap/4-1’
== Spawn extension (mytest, 18884500650, 1) exited non-zero on ‘SIP/501-08e8a468’

The above one worked it dialed the number and I was able to get
the automated attendant

-- Executing Dial("SIP/507-08e87808", "Zap/4/18884500650") in new stack
-- Called 4/18884500650
-- Zap/4-1 is ringing
-- Hungup 'Zap/4-1'

== Spawn extension (mytest, 18884500650, 1) exited non-zero on 'SIP/507-08e87808’
asterisk1*CLI>

The above one did not work. Phone rang but nothing picked up. Not the
right number.

These are two different phones and even when I reconfigure them to
the same SIP id 507 the same behaviour always is true. One phone
a GrandStream sip phone works everytime and the other an analogue
phone through a linksys sip converter does not work. When I look at
the asterisk CLI it is not obvious that anything is different.

WASSUP please.

wct

AND HERE IS a “full” log of a successful and unsuccessful call.

It looks like is the beginning of the successful call

Jun 7 13:01:31 DEBUG[3908] chan_sip.c: Checking SIP call limits for device 501
Jun 7 13:01:31 DEBUG[3908] chan_sip.c: build_route: Contact hop: <sip:501@192.1 68.0.88:5060>
Jun 7 13:01:31 VERBOSE[4511] logger.c: – Executing Dial(“SIP/501-08e87808” , “Zap/4/18884500650”) in new stack
Jun 7 13:01:31 DEBUG[4511] dsp.c: dsp busy pattern set to 0,0
Jun 7 13:01:31 DEBUG[4511] chan_zap.c: Dialing ‘18884500650’
Jun 7 13:01:31 DEBUG[4511] chan_zap.c: Deferring dialing…
Jun 7 13:01:31 VERBOSE[4511] logger.c: – Called 4/18884500650
Jun 7 13:01:32 DEBUG[4511] chan_zap.c: Exception on 18, channel 4
Jun 7 13:01:32 DEBUG[4511] chan_zap.c: Got event Hook Transition Complete(12) o n channel 4 (index 0)
Jun 7 13:01:34 DEBUG[4511] chan_zap.c: Exception on 18, channel 4
Jun 7 13:01:34 DEBUG[4511] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0)
Jun 7 13:01:34 DEBUG[4511] chan_zap.c: Enabled echo cancellation on channel 4
Jun 7 13:01:34 DEBUG[4511] chan_zap.c: Engaged echo training on channel 4
Jun 7 13:01:36 DEBUG[4511] chan_zap.c: Exception on 18, channel 4
Jun 7 13:01:36 DEBUG[4511] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0)
Jun 7 13:01:36 DEBUG[4511] chan_zap.c: Echo cancellation already on
Jun 7 13:01:36 DEBUG[4511] chan_zap.c: Done dialing, but waiting for progress d etection before doing more…
Jun 7 13:01:36 DEBUG[4511] chan_sip.c: Oooh, format changed to 2
Jun 7 13:01:39 VERBOSE[4511] logger.c: – Zap/4-1 is ringing
Jun 7 13:02:00 DEBUG[3908] chan_sip.c: Auto destroying call ‘3591409300@192.168 .0.117’
Jun 7 13:02:04 DEBUG[4511] chan_zap.c: Exception on 18, channel 4
Jun 7 13:02:04 DEBUG[4511] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0)
Jun 7 13:02:04 DEBUG[4511] chan_zap.c: Echo cancellation already on
Jun 7 13:02:04 DEBUG[4511] chan_zap.c: Done dialing, but waiting for progress d etection before doing more…
Jun 7 13:02:10 DEBUG[4511] chan_zap.c: Hangup: channel: 4 index = 0, normal = 1 8, callwait = -1, thirdcall = -1
Jun 7 13:02:10 DEBUG[4511] chan_zap.c: disabled echo cancellation on channel 4
Jun 7 13:02:10 DEBUG[4511] chan_zap.c: Set option TDD MODE, value: OFF(0) on Za p/4-1
Jun 7 13:02:10 DEBUG[4511] chan_zap.c: Updated conferencing on 4, with 0 confer ence users
Jun 7 13:02:10 VERBOSE[4511] logger.c: – Hungup ‘Zap/4-1’
Jun 7 13:02:10 DEBUG[4511] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Jun 7 13:02:10 VERBOSE[4511] logger.c: == Spawn extension (mytest, 1888450065 0, 1) exited non-zero on ‘SIP/501-08e87808’
Jun 7 13:02:10 DEBUG[4511] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record .
Jun 7 13:02:10 DEBUG[4511] cdr_addon_mysql.c: cdr_mysql: SQL command as follows : INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,las tdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2007- 06-07 13:01:31’,’“Engineering” <501>’,‘501’,‘18884500650’,‘mytest’, ‘SIP/501-0 8e87808’,‘Zap/4-1’,‘Dial’,‘Zap/4/18884500650’,39,0,‘NO ANSWER’,3,’’,‘1181246491. 50’)
Jun 7 13:02:10 DEBUG[4511] chan_sip.c: update_call_counter(501) - decrement cal l limit counter
Jun 7 13:02:12 DEBUG[3908] chan_sip.c: SIP message could not be handled, bad re quest: c47afce003221de2@192.168.0.88
Jun 7 13:02:25 DEBUG[3911] manager.c: Manager received command 'Command’
Jun 7 13:02:25 DEBUG[3911] manager.c: Manager received command 'Command’
Jun 7 13:02:25 DEBUG[3911] manager.c: Manager received command 'Command’
Jun 7 13:02:26 DEBUG[3908] chan_sip.c: Setting NAT on RTP to 524288
Jun 7 13:02:26 DEBUG[3908] chan_sip.c: Stopping retransmission on ‘fd4262ce-b6f 2df7@192.168.0.60’ of Response 101: Match Found
Jun 7 13:02:26 DEBUG[3908] chan_sip.c: Setting NAT on RTP to 524288
Jun 7 13:02:26 DEBUG[3908] chan_sip.c: Checking SIP call limits for device 507

IT LOOKS LIKE 507 the unsuccessful call starts here

Jun 7 13:02:26 DEBUG[3908] chan_sip.c: build_route: Contact hop: General <sip:5 07@192.168.0.60:5060>
Jun 7 13:02:26 VERBOSE[4520] logger.c: – Executing Dial(“SIP/507-08e8e628” , “Zap/4/18884500650”) in new stack
Jun 7 13:02:26 DEBUG[4520] dsp.c: dsp busy pattern set to 0,0
Jun 7 13:02:26 DEBUG[4520] chan_zap.c: Dialing '18884500650’
Jun 7 13:02:26 DEBUG[4520] chan_zap.c: Deferring dialing…
Jun 7 13:02:26 DEBUG[3891] channel.c: Avoiding initial deadlock for 'Zap/4-1’
Jun 7 13:02:26 DEBUG[3891] channel.c: Avoiding initial deadlock for ‘Zap/4-1’
Jun 7 13:02:26 VERBOSE[4520] logger.c: – Called 4/18884500650
Jun 7 13:02:26 DEBUG[4520] chan_zap.c: Exception on 18, channel 4
Jun 7 13:02:26 DEBUG[4520] chan_zap.c: Got event Hook Transition Complete(12) o n channel 4 (index 0)
Jun 7 13:02:28 DEBUG[4520] chan_zap.c: Exception on 18, channel 4
Jun 7 13:02:28 DEBUG[4520] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0)
Jun 7 13:02:28 DEBUG[4520] chan_zap.c: Enabled echo cancellation on channel 4
Jun 7 13:02:28 DEBUG[4520] chan_zap.c: Engaged echo training on channel 4
Jun 7 13:02:30 WARNING[3908] chan_sip.c: Maximum retries exceeded on transmissi on c47afce003221de2@192.168.0.88 for seqno 21317 (Critical Response)
Jun 7 13:02:31 DEBUG[4520] chan_zap.c: Exception on 18, channel 4
Jun 7 13:02:31 DEBUG[4520] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0)
Jun 7 13:02:31 DEBUG[4520] chan_zap.c: Echo cancellation already on
Jun 7 13:02:31 DEBUG[4520] chan_zap.c: Done dialing, but waiting for progress d etection before doing more…
Jun 7 13:02:33 VERBOSE[4520] logger.c: – Zap/4-1 is ringing
Jun 7 13:02:55 DEBUG[3908] chan_sip.c: Auto destroying call ‘3591409300@192.168 .0.117’
Jun 7 13:03:27 VERBOSE[4520] logger.c: – Zap/4-1 answered SIP/507-08e8e628
Jun 7 13:03:27 DEBUG[3908] chan_sip.c: Stopping retransmission on ‘fd4262ce-b6f 2df7@192.168.0.60’ of Response 102: Match Found
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: Exception on 18, channel 4
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: Got event On hook(1) on channel 4 (index 0)
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: disabled echo cancellation on channel 4
Jun 7 13:03:27 DEBUG[4520] channel.c: Didn’t get a frame from channel: Zap/4-1
Jun 7 13:03:27 DEBUG[4520] channel.c: Bridge stops bridging channels SIP/507-08 e8e628 and Zap/4-1
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: Hangup: channel: 4 index = 0, normal = 1 8, callwait = -1, thirdcall = -1
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: disabled echo cancellation on channel 4
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: Set option TDD MODE, value: OFF(0) on Za p/4-1
Jun 7 13:03:27 DEBUG[4520] chan_zap.c: Updated conferencing on 4, with 0 confer ence users
Jun 7 13:03:27 VERBOSE[4520] logger.c: – Hungup ‘Zap/4-1’
Jun 7 13:03:27 DEBUG[4520] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jun 7 13:03:27 VERBOSE[4520] logger.c: == Spawn extension (mytest, 1888450065 0, 1) exited non-zero on ‘SIP/507-08e8e628’
Jun 7 13:03:27 DEBUG[4520] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record .
Jun 7 13:03:27 DEBUG[4520] cdr_addon_mysql.c: cdr_mysql: SQL command as follows : INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,las tdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES (‘2007- 06-07 13:02:26’,’“General” <507>’,‘507’,‘18884500650’,‘mytest’, ‘SIP/507-08e8e 628’,‘Zap/4-1’,‘Dial’,‘Zap/4/18884500650’,61,0,‘ANSWERED’,3,’’,‘1181246546.52’)
Jun 7 13:03:27 DEBUG[4520] chan_sip.c: update_call_counter(507) - decrement cal l limit counter
Jun 7 13:03:27 DEBUG[3908] chan_sip.c: Stopping retransmission on ‘fd4262ce-b6f 2df7@192.168.0.60’ of Request 102: Match Found
Jun 7 13:03:50 DEBUG[3908] chan_sip.c: Auto destroying call ‘3591409300@192.168 .0.117’
[root@asterisk1 asterisk]# 166