ASTERISK-08254: AgentCallbackLogin and SIP hold music doesn't work in user to agent direction.

[Home]

Summary: ASTERISK-08254: AgentCallbackLogin and SIP hold music doesn't work in user to agent direction.

Reporter: dmb (dmb) Labels:

Date Opened: 2006-12-01 05:06:15.000-0600 Date Closed: 2006-12-01 10:30:25.000-0600

Priority: Minor Regression? No

Status: Closed/Complete Components: Resources/res_musiconhold

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments:

Description: In 0005866 somebody reports:
"I have a queue with agents that are callback agents using SIP phones. When a caller calls into the queue they hear the hold music just fine, however once connected to an agent, if the caller puts the agent on hold, the following scrolls on the console:
.....
"
I have the same problem. In additional information are thre full trace

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

The call arrives from xlite 1005 to agent/5006 logged from SIP/1004 via queue 102
[Dec 1 11:56:19] DEBUG[9730] manager.c: Manager received command 'Ping'
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [102@from-internal:1] Answer("SIP/1005-08921470", "") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [102@from-internal:2] Macro("SIP/1005-08921470", "dumpvars") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:1] NoOp("SIP/1005-08921470", "ACCOUNTCODE=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:2] NoOp("SIP/1005-08921470", "ANSWEREDTIME=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:3] NoOp("SIP/1005-08921470", "BLINDTRANSFER=") in new stack
[Dec 1 11:56:28] DEBUG[10920] pbx.c: Function result is '"1005" <1005>'
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:4] NoOp("SIP/1005-08921470", "CALLERID="1005" <1005>") in new stack
[Dec 1 11:56:28] DEBUG[10920] pbx.c: Function result is '1005'
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:5] NoOp("SIP/1005-08921470", "CALLERID(name)=1005") in new stack
[Dec 1 11:56:28] DEBUG[10920] pbx.c: Function result is '1005'
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:6] NoOp("SIP/1005-08921470", "CALLERID(number)=1005") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:7] NoOp("SIP/1005-08921470", "CALLINGPRES=0") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:8] NoOp("SIP/1005-08921470", "CHANNEL=SIP/1005-08921470") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:9] NoOp("SIP/1005-08921470", "CONTEXT=macro-dumpvars") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:10] NoOp("SIP/1005-08921470", "DATETIME=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:11] NoOp("SIP/1005-08921470", "DIALEDPEERNAME=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:12] NoOp("SIP/1005-08921470", "DIALEDPEERNUMBER=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:13] NoOp("SIP/1005-08921470", "DIALEDTIME=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:14] NoOp("SIP/1005-08921470", "DIALSTATUS=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:15] NoOp("SIP/1005-08921470", "DNID=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:16] NoOp("SIP/1005-08921470", "EPOCH=1164970588") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:17] NoOp("SIP/1005-08921470", "EXTEN=s") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:18] NoOp("SIP/1005-08921470", "HANGUPCAUSE=0") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:19] NoOp("SIP/1005-08921470", "INVALID_EXTEN=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:20] NoOp("SIP/1005-08921470", "LANGUAGE=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:21] NoOp("SIP/1005-08921470", "MEETMESECS=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:22] NoOp("SIP/1005-08921470", "PRIORITY=22") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:23] NoOp("SIP/1005-08921470", "RDNIS=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:24] NoOp("SIP/1005-08921470", "SIPDOMAIN=192.168.0.224") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:25] NoOp("SIP/1005-08921470", "SIP_CODEC=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:26] NoOp("SIP/1005-08921470", "SIPCALLID=176c3c0daa5d522aZDgzZjNkNzJhNTQ4MDIzYmQ3YjRiMDY2ZDkzZjFhYTc.") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:27] NoOp("SIP/1005-08921470", "SIPUSERAGENT=X-Lite release 1002tx stamp 29712") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:28] NoOp("SIP/1005-08921470", "TIMESTAMP=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:29] NoOp("SIP/1005-08921470", "TXTCIDNAME=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:30] NoOp("SIP/1005-08921470", "UNIQUEID=1164970588.225") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:31] NoOp("SIP/1005-08921470", "TOUCH_MONITOR=") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:32] NoOp("SIP/1005-08921470", "MACRO_CONTEXT=from-internal") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:33] NoOp("SIP/1005-08921470", "MACRO_EXTEN=102") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [s@macro-dumpvars:34] NoOp("SIP/1005-08921470", "MACRO_PRIORITY=2") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [102@from-internal:3] Set("SIP/1005-08921470", "CALLERID(number)=102") in new stack
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Executing [102@from-internal:4] Queue("SIP/1005-08921470", "102|nt|||20") in new stack
[Dec 1 11:56:28] DEBUG[10920] app_queue.c: Estado de agente [Agent/5006]: [1], Paused [0]
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Started music on hold, class 'default', on SIP/1005-08921470
[Dec 1 11:56:28] DEBUG[10920] channel.c: Scheduling timer at 160 sample intervals
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- outgoing agentcall, to agent '5006', on 'Local/1004@from-internal-b3f6,1'
[Dec 1 11:56:28] WARNING[10920] interface.c: Junk at the beginning of frame 49443303
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [1004@from-internal:1] Macro("Local/1004@from-internal-b3f6,2", "exten-vm|novm|1004") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:1] Macro("Local/1004@from-internal-b3f6,2", "user-callerid") in new stack
[Dec 1 11:56:28] DEBUG[10920] channel.c: Scheduling timer at 0 sample intervals
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Expression result is '1'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-user-callerid:1] GotoIf("Local/1004@from-internal-b3f6,2", "1?report") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Goto (macro-user-callerid,s,9)
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Function result is '"1005" <102>'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-user-callerid:9] NoOp("Local/1004@from-internal-b3f6,2", "Using CallerID "1005" <102>") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:2] Set("Local/1004@from-internal-b3f6,2", "FROMCONTEXT=exten-vm") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:3] Set("Local/1004@from-internal-b3f6,2", "VMBOX=novm") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:4] Set("Local/1004@from-internal-b3f6,2", "EXTTOCALL=1004") in new stack
[Dec 1 11:56:28] DEBUG[10922] db.c: Unable to find key '1004' in family 'CFU'
[Dec 1 11:56:28] DEBUG[10922] func_db.c: DB: CFU/1004 not found in database.
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Function result is ''
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:5] Set("Local/1004@from-internal-b3f6,2", "CFUEXT=") in new stack
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Expression result is '0'
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Expression result is '0'
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Expression result is '0'
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Function result is ''
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:6] Set("Local/1004@from-internal-b3f6,2", "RT=") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:7] Macro("Local/1004@from-internal-b3f6,2", "record-enable|1004|IN") in new stack
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Function result is '0'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("Local/1004@from-internal-b3f6,2", "0 > 0?2:4") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Goto (macro-record-enable,s,4)
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-record-enable:4] AGI("Local/1004@from-internal-b3f6,2", "recordingcheck||1164970588.227") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Dec 1 11:56:28] VERBOSE[10922] logger.c: recordingcheck||1164970588.227: Inbound recording not enabled
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- AGI Script recordingcheck completed, returning 0
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-record-enable:5] NoOp("Local/1004@from-internal-b3f6,2", "No recording needed") in new stack
[Dec 1 11:56:28] DEBUG[10922] pbx.c: Expression result is '1'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-exten-vm:8] GotoIf("Local/1004@from-internal-b3f6,2", "1?dolocaldial|1") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Goto (macro-exten-vm,dolocaldial,1)
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [dolocaldial@macro-exten-vm:1] Macro("Local/1004@from-internal-b3f6,2", "dial||tr|1004") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:1] NoOp("Local/1004@from-internal-b3f6,2", "1164970588.227") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:2] Set("Local/1004@from-internal-b3f6,2", "1164970588.227=mierda") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:3] NoOp("Local/1004@from-internal-b3f6,2", "mierda") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:4] SIPAddHeader("Local/1004@from-internal-b3f6,2", "Call-Info:;answer-after=0") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:5] AGI("Local/1004@from-internal-b3f6,2", "dialparties.agi") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Dec 1 11:56:28] VERBOSE[10922] logger.c: dialparties.agi: Starting New Dialparties.agi
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- dialparties.agi: priority is 1
[Dec 1 11:56:28] VERBOSE[10922] logger.c: dialparties.agi: Caller ID name is '1005' number is '102'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: dialparties.agi: Methodology of ring is 'none'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- dialparties.agi: Added extension 1004 to extension map
[Dec 1 11:56:28] DEBUG[10922] db.c: Unable to find key '1004' in family 'CF'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- dialparties.agi: Extension 1004 cf is disabled
[Dec 1 11:56:28] DEBUG[10922] db.c: Unable to find key '1004' in family 'DND'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- dialparties.agi: Extension 1004 do not disturb is disabled
[Dec 1 11:56:28] DEBUG[10922] db.c: Unable to find key '1004' in family 'CFB'
[Dec 1 11:56:28] DEBUG[10922] db.c: Unable to find key '1004' in family 'CFU'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: extnum: 1004
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: exthascw: 1
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: exthascfb: 0
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: extcfb:
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: exthascfu: 0
[Dec 1 11:56:28] VERBOSE[10922] logger.c: > dialparties.agi: extcfu:
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- dialparties.agi: DbSet CALLTRACE/1004 to 102
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Executing [s@macro-dial:10] Dial("Local/1004@from-internal-b3f6,2", "SIP/1004||tr") in new stack
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- Called 1004
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Agent/5006 is ringing
[Dec 1 11:56:28] VERBOSE[10922] logger.c: -- SIP/1004-0893ae78 answered Local/1004@from-internal-b3f6,2
[Dec 1 11:56:28] DEBUG[10920] app_queue.c: Dunno what to do with control type -1
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Agent/5006 answered SIP/1005-08921470
[Dec 1 11:56:28] VERBOSE[10920] logger.c: -- Stopped music on hold on SIP/1005-08921470
[Dec 1 11:56:28] DEBUG[10920] channel.c: Scheduling timer at 0 sample intervals
[Dec 1 11:56:28] DEBUG[10922] channel.c: Planning to masquerade channel SIP/1004-0893ae78 into the structure of Local/1004@from-internal-b3f6,1
[Dec 1 11:56:28] DEBUG[10922] channel.c: Done planning to masquerade channel SIP/1004-0893ae78 into the structure of Local/1004@from-internal-b3f6,1
[Dec 1 11:56:28] DEBUG[10920] channel.c: Released clone lock on 'Local/1004@from-internal-b3f6,1<ZOMBIE>'
[Dec 1 11:56:28] DEBUG[10920] chan_agent.c: Bridge on 'SIP/1004-0893ae78' being set to 'Agent/5006' (3)
[Dec 1 11:56:28] DEBUG[10922] channel.c: Didn't get a frame from channel: Local/1004@from-internal-b3f6,1<ZOMBIE>
[Dec 1 11:56:28] DEBUG[10922] channel.c: Bridge stops bridging channels Local/1004@from-internal-b3f6,2 and Local/1004@from-internal-b3f6,1<ZOMBIE>
[Dec 1 11:56:28] VERBOSE[10922] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/1004@from-internal-b3f6,2' in macro 'dial'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/1004@from-internal-b3f6,2' in macro 'exten-vm'
[Dec 1 11:56:28] VERBOSE[10922] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/1004@from-internal-b3f6,2'
[Dec 1 11:56:28] DEBUG[10922] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Dec 1 11:56:28] DEBUG[10922] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-12-01 11:56:28','\"1005\" <102>','102','1004','from-internal', 'Local/1004@from-internal-b3f6,2','SIP/1004-0893ae78','Dial','SIP/1004||tr',0,0,'ANSWERED',3,'')
[Dec 1 11:56:31] DEBUG[9730] manager.c: Manager received command 'QueuePause'
[Dec 1 11:56:32] DEBUG[9730] manager.c: Manager received command 'Monitor'

The xlite clicks hold button:

[Dec 1 12:04:30] DEBUG[9720] app_infglobalcall.c: CTIGLOBALCALL - DBG - GLOBALCALL Total llamadas 0
[Dec 1 12:04:35] DEBUG[9720] app_infglobalcall.c: CTIGLOBALCALL - DBG - GLOBALCALL Total llamadas 0
[Dec 1 12:04:35] VERBOSE[10920] logger.c: -- Started music on hold, class 'default', on SIP/1004-0893ae78
[Dec 1 12:04:35] DEBUG[10920] channel.c: Scheduling timer at 160 sample intervals
[Dec 1 12:04:35] WARNING[10920] interface.c: Junk at the beginning of frame 49443303
[Dec 1 12:04:35] DEBUG[10920] channel.c: Scheduling timer at 0 sample intervals
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:35] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:36] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:36] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
[Dec 1 12:04:36] WARNING[10920] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x4 (ulaw)(4) read/write = 0x4 (ulaw)(4)/0x4 (ulaw)(4)
... this repeats until xlite unhold the call.

Thanks

Comments: By: Serge Vecher (serge-v) 2006-12-01 10:30:25.000-0600

the proper thing to do, when encountering a suspended bug, is to ask a bug marshal to reopen the issue, which I have just done for you. Please attach the debug information there.