Hi
I have a server running Asterisk 1.4.18 on a Debian etch 2.6.18-5-amd64 with a TE120P card.
When i call SIP->SIP or Zap-SIP and the called end puts the call on hold or uses another line, the original call drops after ~30 sec of hear the music on hold.
Any clue?
Here is the debug log (without some “Internal timing is enable…” lines):
[code][Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Macro’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [8137@numberplan-custom-5:1] Macro(“SIP/8117-0085d4a0”, “stdexten|8137|SIP/8137”) in new stack
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Set’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:1] Set(“SIP/8117-0085d4a0”, “exten=8137”) in new stack
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: Set
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Set’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:2] Set(“SIP/8117-0085d4a0”, “device=SIP/8137”) in new stack
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: Set
[Feb 9 18:46:27] DEBUG[13265] db.c: Unable to find key ‘8137’ in family ‘CFIM’
[Feb 9 18:46:27] DEBUG[13265] func_db.c: DB: CFIM/8137 not found in database.
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Function result is ‘’
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Set’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:3] Set(“SIP/8117-0085d4a0”, “temp=”) in new stack
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: Set
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Verbose’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:4] Verbose(“SIP/8117-0085d4a0”, “0| CALL: 1202593587.2:SIP/8137”) in new stack
[Feb 9 18:46:27] VERBOSE[13265] logger.c: CALL: 1202593587.2:SIP/8137
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: Verbose
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘MixMonitor’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:5] MixMonitor(“SIP/8117-0085d4a0”, “1202593587.2.wav”) in new stack
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: MixMonitor
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘GotoIf’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:6] GotoIf(“SIP/8117-0085d4a0”, “?cfim:nocfim”) in new stack
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Goto (macro-stdexten,s,8)
[Feb 9 18:46:27] DEBUG[13265] app_macro.c: Executed application: GotoIf
[Feb 9 18:46:27] DEBUG[13265] pbx.c: Launching ‘Dial’
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Executing [s@macro-stdexten:8] Dial(“SIP/8117-0085d4a0”, “SIP/8137||tT”) in new stack
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Setting NAT on RTP to Off
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: *** Our native formats are 0x2 (gsm)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: *** Our capabilities are 0x2 (gsm)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: This channel will not be able to handle video.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable MACRO_DEPTH.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable temp.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable device.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable exten.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable ARG2.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable ARG1.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable MACRO_PRIORITY.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable MACRO_CONTEXT.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable MACRO_EXTEN.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable SIPCALLID.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable SIPUSERAGENT.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable SIPDOMAIN.
[Feb 9 18:46:27] DEBUG[13265] channel.c: Not copying variable SIPURI.
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Outgoing Call for 8137
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Updating call counter for outgoing call
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: False
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: ** Our prefcodec: 0x4 (ulaw)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: – Done with adding codecs to SDP
[Feb 9 18:46:27] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=69)
[Feb 9 18:46:27] DEBUG[13265] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm)
[Feb 9 18:46:27] VERBOSE[13265] logger.c: – Called 8137
[Feb 9 18:46:27] DEBUG[13265] channel.c: Set channel SIP/8137-00864650 to read format slin
[Feb 9 18:46:27] DEBUG[13265] channel.c: Set channel SIP/8117-0085d4a0 to write format slin
[Feb 9 18:46:27] DEBUG[13265] channel.c: Set channel SIP/8117-0085d4a0 to read format slin
[Feb 9 18:46:27] DEBUG[13265] channel.c: Set channel SIP/8137-00864650 to write format slin
[Feb 9 18:46:28] VERBOSE[13265] logger.c: – SIP/8137-00864650 is ringing
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Got RTCP report of 132 bytes
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: Setting framing from config on incoming call
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: ** Our capability: 0x60c (ulaw|alaw|speex|ilbc) Video flag: True
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: – Done with adding codecs to SDP
[Feb 9 18:46:32] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: Done building SDP. Settling with this capability: 0x60c (ulaw|alaw|speex|ilbc)
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Ooh, format changed from unknown to ulaw
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Got RTCP report of 132 bytes
[Feb 9 18:46:32] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8137-00864650
[Feb 9 18:46:32] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8137
[Feb 9 18:46:32] VERBOSE[13265] logger.c: – SIP/8137-00864650 answered SIP/8117-0085d4a0
[Feb 9 18:46:32] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8117-0085d4a0
[Feb 9 18:46:32] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8117
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: SIP answering channel: SIP/8117-0085d4a0
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: Setting framing from config on incoming call
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: ** Our capability: 0x60c (ulaw|alaw|speex|ilbc) Video flag: True
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: – Done with adding codecs to SDP
[Feb 9 18:46:32] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:32] DEBUG[13265] chan_sip.c: Done building SDP. Settling with this capability: 0x60c (ulaw|alaw|speex|ilbc)
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Ooh, format changed from unknown to gsm
[Feb 9 18:46:32] DEBUG[13265] rtp.c: Created smoother: format: 2 ms: 20 len: 33
[Feb 9 18:46:35] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:36] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:38] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:38] DEBUG[13265] rtp.c: Got RTCP report of 44 bytes
[Feb 9 18:46:38] DEBUG[13265] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.4.186:11205
[Feb 9 18:46:39] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:41] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:42] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:44] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:44] DEBUG[13265] rtp.c: Got RTCP report of 44 bytes
[Feb 9 18:46:44] DEBUG[13265] rtp.c: Unknown RTCP packet (pt=207) received from 192.168.4.186:11205
[Feb 9 18:46:46] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:47] DEBUG[13265] rtp.c: Got RTCP report of 176 bytes
[Feb 9 18:46:49] VERBOSE[13265] logger.c: – Started music on hold, class ‘default’, on channel ‘SIP/8117-0085d4a0’
[Feb 9 18:46:49] DEBUG[13265] channel.c: Scheduling timer at 160 sample intervals
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:46:49] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
…
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] rtp.c: Got RTCP report of 44 bytes
[Feb 9 18:47:08] DEBUG[13265] rtp.c: Unknown RTCP packet (pt=207) received from 0.0.0.0:0
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] rtp.c: Got RTCP report of 156 bytes
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:08] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
…
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] rtp.c: Got RTCP report of 164 bytes
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=65)
[Feb 9 18:47:17] DEBUG[13265] channel.c: Didn’t get a frame from channel: SIP/8137-00864650
[Feb 9 18:47:17] DEBUG[13265] channel.c: Bridge stops bridging channels SIP/8117-0085d4a0 and SIP/8137-00864650
[Feb 9 18:47:17] DEBUG[13265] channel.c: Hanging up channel ‘SIP/8137-00864650’
[Feb 9 18:47:17] DEBUG[13265] chan_sip.c: Hangup call SIP/8137-00864650, SIP callid 080051827a479bab5b1c010827129c77@192.168.4.240)
[Feb 9 18:47:17] DEBUG[13265] chan_sip.c: Updating call counter for outgoing call
[Feb 9 18:47:17] DEBUG[13265] chan_sip.c: Call to peer ‘8137’ removed from call limit 0
[Feb 9 18:47:17] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8137
[Feb 9 18:47:17] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8137-00864650
[Feb 9 18:47:17] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8137
[Feb 9 18:47:17] DEBUG[13265] rtp.c: Channel ‘’ has no RTP, not doing anything
[Feb 9 18:47:17] DEBUG[13265] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Feb 9 18:47:17] DEBUG[13265] app_macro.c: Spawn extension (macro-stdexten,s,8) exited non-zero on ‘SIP/8117-0085d4a0’ in macro ‘stdexten’
[Feb 9 18:47:17] DEBUG[13265] pbx.c: Spawn extension (macro-stdexten,s,8) exited non-zero on ‘SIP/8117-0085d4a0’
[Feb 9 18:47:17] VERBOSE[13265] logger.c: == Spawn extension (macro-stdexten, s, 8) exited non-zero on ‘SIP/8117-0085d4a0’
[Feb 9 18:47:17] DEBUG[13265] channel.c: Soft-Hanging up channel ‘SIP/8117-0085d4a0’
[Feb 9 18:47:17] DEBUG[13265] channel.c: Set channel SIP/8117-0085d4a0 to write format slin
[Feb 9 18:47:17] VERBOSE[13265] logger.c: – Stopped music on hold on SIP/8117-0085d4a0
[Feb 9 18:47:17] DEBUG[13265] channel.c: Hanging up channel ‘SIP/8117-0085d4a0’
[Feb 9 18:47:17] DEBUG[13265] chan_sip.c: Hangup call SIP/8117-0085d4a0, SIP callid NTJkYzYxMzc3MWIwNmMxZjUxZmIxZDk0MTc5NTljNTk.)
[Feb 9 18:47:17] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8117-0085d4a0
[Feb 9 18:47:17] DEBUG[13265] devicestate.c: Notification of state change to be queued on device/channel SIP/8117
[Feb 9 18:47:17] DEBUG[13265] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Feb 9 18:47:17] DEBUG[13265] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES (‘2008-02-09 18:46:27’,’“XXX” <8117>’,‘8117’,‘8137’,‘numberplan-custom-5’, ‘SIP/8117-0085d4a0’,‘SIP/8137-00864650’,‘Dial’,‘SIP/8137||tT’,50,45,‘ANSWERED’,3,’’,‘1202593587.2’,’’)
[/code]