When I call the number I get the main IVR which plays fine, option 1 plays fine but the others are delayed, one worse than the other. I verified that the worst one doesn’t have any dead space on the wav file as it was just updated today. I also don’t see any issues in the logs.
I am running distro version 5.211.65-9 IVR module 2.11.05
[2014-04-15 15:34:46] VERBOSE[21510][C-00002521] file.c: – <SIP/PROVIDER-00004788> Playing ‘custom/IVR_Business_Hours_11-08-2012.slin’ (language ‘en’)
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: == CDR updated on SIP/PROVIDER-00004788
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [3@ivr-7:1] Set(“SIP/PROVIDER-00004788”, “IVRSELECTION=3|ivr-7”) in new stack
[2014-04-15 15:34:52] WARNING[21510][C-00002521] pbx.c: The application delimiter is now the comma, not the pipe. Did you forget to convert your dialplan? (Set(IVRSELECTION=3|ivr-7))
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [3@ivr-7:2] QueueLog(“SIP/PROVIDER-00004788”, “NONE,1397601285.24052,NONE,INFO,IVRAPPEND|3|ivr-7”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [3@ivr-7:3] Goto(“SIP/PROVIDER-00004788”, “ivr-5,s,1”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Goto (ivr-5,s,1)
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:1] Set(“SIP/PROVIDER-00004788”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:2] Set(“SIP/PROVIDER-00004788”, “INVALID_LOOPCOUNT=0”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:3] Set(“SIP/PROVIDER-00004788”, “_IVR_CONTEXT_ivr-5=ivr-7”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:4] Set(“SIP/PROVIDER-00004788”, “_IVR_CONTEXT=ivr-5”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:5] Set(“SIP/PROVIDER-00004788”, “__IVR_RETVM=”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:6] GotoIf(“SIP/PROVIDER-00004788”, “1?skip”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Goto (ivr-5,s,9)
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:9] Set(“SIP/PROVIDER-00004788”, “IVR_MSG=custom/IVR_Accounting_v1”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:10] Set(“SIP/PROVIDER-00004788”, “TIMEOUT(digit)=3”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] func_timeout.c: – Digit timeout set to 3.000
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] pbx.c: – Executing [s@ivr-5:11] ExecIf(“SIP/PROVIDER-00004788”, “1?Background(custom/IVR_Accounting_v1)”) in new stack
[2014-04-15 15:34:52] VERBOSE[21510][C-00002521] file.c: – <SIP/PROVIDER-00004788> Playing ‘custom/IVR_Accounting_v1.slin’ (language ‘en’)
bump
I don’t see anything in the log either, looks like the file played in the same second as button pushed.
Have you done an rtp debug to see if there is any delay in the start of transmission of media.
Would I just want to do “rtp debug” from the Asterisk CLI and press the buttons to see if there is a delay? Or are yout hinking there are errors? its just strange because if I press option 1 its fine and plays right away.
With no other calls start the rtp debug. press button. If rtp packets cease then start when the voice starts it’s something in the system. If RTP starts right away it’s external.
I have a backup PBX so I tried it on there since its easier to get no traffic on that one. When I pressed the key I did get some debug things but I dunno what they mean.
Got RTP packet from SIP_IP:19578 (type 00, seq 001363, ts 218080, len 000160)
Got RTP packet from SIP_IP:19578 (type 00, seq 001364, ts 218240, len 000160)
Got RTP packet from SIP_IP:19578 (type 00, seq 001365, ts 218400, len 000160)
Got RTP packet from SIP_IP:19578 (type 00, seq 001366, ts 218560, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001367, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001367, ts 218640, len 000004, mark 1, event 00000002, end 0, duration 00000)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001368, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001368, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00080)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001369, ts 218720, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001370, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001370, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00160)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001371, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001371, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00240)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001372, ts 218880, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001373, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001373, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00320)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001374, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001374, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00400)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001375, ts 219040, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001376, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001376, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00480)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001377, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001377, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00560)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001378, ts 219200, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001379, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001379, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00640)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001380, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001380, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00720)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001381, ts 219360, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001382, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001382, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00800)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001383, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001383, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00880)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001384, ts 219520, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001385, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001385, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 00960)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001386, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001386, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 01040)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001387, ts 219680, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001388, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001388, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 01120)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001389, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001389, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 01200)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001390, ts 219840, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001391, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001391, ts 218640, len 000004, mark 0, event 00000002, end 0, duration 01280)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001392, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001392, ts 218640, len 000004, mark 0, event 00000002, end 1, duration 01360)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001393, ts 220000, len 000160)
Got RTP packet from SIP_IP:19578 (type 101, seq 001394, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001394, ts 218640, len 000004, mark 0, event 00000002, end 1, duration 01360)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 101, seq 001395, ts 218640, len 000004)
Got RTP RFC2833 from SIP_IP:19578 (type 101, seq 001395, ts 218640, len 000004, mark 0, event 00000002, end 1, duration 01360)
[2014-04-21 17:59:43] DEBUG[3832][C-0000000a]: res_rtp_asterisk.c:2907 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
Got RTP packet from SIP_IP:19578 (type 00, seq 001396, ts 220160, len 000160)
Got RTP packet from SIP_IP:19578 (type 00, seq 001397, ts 220320, len 000160)
Got RTP packet from SIP_IP:19578 (type 00, seq 001398, ts 220480, len 000160)
That doesn’t help me because I can’t temporally correlate it with the voice.
Do the RTP packets start before you hear the voice?
Also do a core set verbose 0 and a core set debug 0 to unclutter the output.
You say you did the experiment on a backup box. Does this box also exhibit the same delay?