Strange Queue delay ringing its agents

wilwil · June 14, 2016, 9:37am

Hello everybody,

To begin with: I’m using asterisk 13.4 (and Freepbx Gui : I really don’t want to use it but it’s a work obligation ).
In fact, I develop a dialer that ring external numbers via Sip Provider, then redirect answered calls to specific queue.

So here is the problem:
Logically, when I have available agent and caller come to this queue ==> Caller and Agent must be bridged in no time (~1 second max) , isn’t right?
But here what I have as results: I’ll give as much as I can of system environment infos to help debugging problem:
Test1: --Asterisk Server in Germany + Agents registered from Serbia-- :: I have strange delay when queue ringing its agents (about 4-5 seconds) when of course we have an available agent and ready caller to talk with.
Test1: --Asterisk Server in Germany + Agents registered from country of north africa-- :: I have an acceptable delay when queue ringing its agents (about 1-2 seconds) when of course we have an available agent and ready caller to talk with.

–Also following the log, I remarked that queue try to call all agents one after one (even there are Unavailable) to redirect a call for an available one. Is this normal ??? Can this participate increasing this delay ???

Here is my queue setup:
[104]
announce-frequency=0
announce-holdtime=no
announce-position=no
answered_elsewhere=0
autofill=yes
autopause=no
autopausebusy=no
autopausedelay=0
autopauseunavail=no
joinempty=yes
leavewhenempty=no
maxlen=0
memberdelay=0
monitor-join=yes
music=none
penaltymemberslimit=0
periodic-announce-frequency=0
queue-callswaiting=silence/1
queue-thereare=silence/1
queue-youarenext=silence/1
reportholdtime=no
retry=0
ringinuse=yes
servicelevel=60
setinterfacevar=yes
strategy=rrmemory
timeout=120
timeoutpriority=app
timeoutrestart=no
weight=0
wrapuptime=0
eventmemberstatus=no
member=Local/@from-queue/n,0,Agent1,hint:@ext-local
member=Local/@from-queue/n,0,Agent2,hint:@ext-local
member=Local/@from-queue/n,0,Agent3,hint:@ext-local

As you can see, I set to 0 “Retry”, “Wrap up Time”, “Member delay” configs to make sure there is no delay while ringing agents. But in vain I always have the same delay.

Please, can you help me debugging this problem: I have doubts in :

Sip Provider delay.
Queue configs.
location of agents % asterisk server OR location of sip provider % asterisk server.
But I really don’t know which of these can cause this problem. Can you help me because this very crucial to me to fix it.

And thanks in advance.

astbox · June 14, 2016, 5:39pm

Ping the box from Serbia and from the North Africa country, what do you get?

david551 · June 14, 2016, 8:55pm

In theory this will depend on what is in the local channel dialplan, although I suspect it is more likely to be something with the Dial application call.

Using FreePBX could make this difficult for us, as FreePBX contributes some rather complex dialplans, so can I ask you to enable millisecond logging in logger.conf, set verbosity to 5 and then discover whether the the delay is before or after the final Dial call. (Unfortunately FreePBX may embed this in AGI scripting.

If it is on the final dial, enable SIP debugging and debug level 5 to find out at what stage in the SIP INVITE transaction the delay is occurring.

If the delay is happening earlier, but after any of your hand crafted dialplan, you need to go to http://community.freepbx.org/ as we cannot debug FreePBX’s dialplans here.

wilwil · June 15, 2016, 8:14am

Thanks for your reply:
For the ping I’ll get the results as soon as possible. And you mean the result of the regular “ping” command from the two sites?

By the way, the server box is located in “Germany”. If this can help.

wilwil · June 15, 2016, 8:22am

You mean by this I must watch carefully Sip log in the stage when a caller waiting in the queue and “Queue dial Agent” ? But is there a way to redirect that log to specific file or can I find it in specific log file to analyze it and let you see it after that ?

wilwil · June 15, 2016, 10:32am

For Ping test:
The test in Serbia: rtt min/avg/max/mdev = 60.838/62.323/64.225/1.300 (where there is the big delay 4-5s)
The test in North Africa country : rtt min/avg/max = 49/49/49 ms (where there is the acceptable delay 1-2s)

wilwil · June 15, 2016, 10:40am

You are probably right, because when I test (from “Serbia site” where there is the big delay) simple call between 2 agents, I remarked a latency from the begin of dial action and the changement of extension state to ringing . Is that normal ?

wilwil · June 15, 2016, 1:26pm

I did as you suggested : I enabled miliseconds in logger.conf.
And as it is very very clear in the log that the 4 seconds are gone in dial action (ringing action) : I mean between "start of Queue Dial agent action " <-----> “Agent answered” .

This is the log:
[2016-06-15 14:40:32.608] VERBOSE[8312][C-00000004] pbx.c: Goto (macro-dial-one,s,43)
[2016-06-15 14:40:32.608] VERBOSE[8312][C-00000004] pbx.c: Executing [s@macro-dial-one:43] Macro(“Local/1001@from-queue-00000002;2”, “dialout-one-predial-hook,”) in new $
[2016-06-15 14:40:32.608] VERBOSE[8312][C-00000004] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit(“Local/1001@from-queue-00000002;2”, “”) in new stack
[2016-06-15 14:40:32.608] VERBOSE[8312][C-00000004] pbx.c: Executing [s@macro-dial-one:44] Dial(“Local/1001@from-queue-00000002;2”, “SIP/1001,TtrM(auto-blkvm)”) in new $
[2016-06-15 14:40:32.621] VERBOSE[8312][C-00000004] netsock2.c: Using SIP RTP TOS bits 184
[2016-06-15 14:40:32.621] VERBOSE[8312][C-00000004] netsock2.c: Using SIP RTP CoS mark 5
[2016-06-15 14:40:32.622] VERBOSE[8312][C-00000004] app_dial.c: Called SIP/1001
[2016-06-15 14:40:32.622] VERBOSE[7951][C-00000004] app_queue.c: Local/1001@from-queue-00000002;1 is ringing
[2016-06-15 14:40:32.767] VERBOSE[8312][C-00000004] app_dial.c: SIP/1001-00000001 is ringing
[2016-06-15 14:40:32.767] VERBOSE[7951][C-00000004] app_queue.c: Local/1001@from-queue-00000002;1 is ringing
[2016-06-15 14:40:32.808] VERBOSE[8312][C-00000004] app_dial.c: SIP/1001-00000001 is ringing
[2016-06-15 14:40:36.515] VERBOSE[8312][C-00000004] app_dial.c: SIP/1001-00000001 answered Local/1001@from-queue-00000002;2

But I add that I use auto-answer feature in agent soft-phone: So the delay was in ringing action !!!

But is that normal for Ringing Action to take so that long ???
Have you any idea about that??

david551 · June 15, 2016, 8:34pm

I think you must have r set on dial, so the initial ringback is faked, but you have, what looks like, an end to end 180 response after 145ms, which is not incompatible with intercontinental terrestrial paths.

Enabling sip debugging (sip set debug on) would give some finer details, but it does look like the delay is at the remove end.

astbox · June 16, 2016, 5:04pm

I don’t think there is a problem with asterisk. If your configuration was wrong you would had the problem in both sites. I think that there is a problem with the internet provider in Serbia. Test again from a different provider.

wilwil · June 21, 2016, 1:58pm

Sorry for the delay. And thanks for your replies.
Brief, I enabled the debug and extracted the log, but I didn’t really figure out the real cause for this. But, I can remark some things might help:

1- what’s happening is that the server is in delay !!! . As the call waiting in queue and just delivered to the specific available agent (decision which available agent, dial that agent ::: happens in some ms) ; its soft-phone answer the call in time (0-1 second delay) , but Asterisk still see the agent in Ringing State for 3-4 seconds (very strange) before it figure that the call was answered and begin send audio RTP trams. (and of course I checked out that several times).

2- Simple calls:
**In internal calls between agents, I tried simple internal call :

(agent in north Africa site) —> to (agent from Serbia site) : there is delay :: second side answer in time but the first side has delay of 3-4 seconds (Ringing for 3-4s). ( not acceptable)
(agent from Serbia site) —> to (agent in north Africa site) : there is delay :: second side answer in time but the first side has delay of 0-1 seconds (Ringing for 0-1s). (acceptable)
** Simple outbound call from Serbia Site: delay of 0-1 seconds between caller and callee (Ringing for 0-1s). (acceptable)

====> I think there is a delay one side server specially “Server —> Agents” not “Agents ----> server” !

3- This is the important : here is the debug log for one case using the queue from Serbia Site:

[2016-06-21 10:58:00.648] VERBOSE[27398][C-00001e36] app_queue.c: Called Local/1011@from-queue/n
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [1011@from-queue:1] Set(“Local/1011@from-queue-000000c8;2”, “QAGENT=1011”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [1011@from-queue:2] Goto(“Local/1011@from-queue-000000c8;2”, “104,1”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Goto (from-queue,104,1)
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [104@from-queue:1] Goto(“Local/1011@from-queue-000000c8;2”, “from-internal,1011,1”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Goto (from-internal,1011,1)
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [1011@from-internal:1] Set(“Local/1011@from-queue-000000c8;2”, “__RINGTIMER=15”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [1011@from-internal:2] Macro(“Local/1011@from-queue-000000c8;2”, “exten-vm,novm,1011,0,0,0”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:1] Macro(“Local/1011@from-queue-000000c8;2”, “user-callerid,”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:1] Set(“Local/1011@from-queue-000000c8;2”, “TOUCH_MONITOR=1466499480.10270”) in new stack
[2016-06-21 10:58:00.648] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:2] Set(“Local/1011@from-queue-000000c8;2”, “AMPUSER=Rached@0021673656042@27_3@141”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?report”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-user-callerid,s,16)
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:16] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?continue”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:17] Set(“Local/1011@from-queue-000000c8;2”, “__TTL=63”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?continue”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-user-callerid,s,29)
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:29] Set(“Local/1011@from-queue-000000c8;2”, “CALLERID(number)=Rached@0021673656042@27_3@141”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:30] Set(“Local/1011@from-queue-000000c8;2”, “CALLERID(name)=Dialer”) in new stack
[2016-06-21 10:58:00.649] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:31] Set(“Local/1011@from-queue-000000c8;2”, “CDR(cnum)=Rached@0021673656042@27_3@141”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:32] Set(“Local/1011@from-queue-000000c8;2”, “CDR(cnam)=Dialer”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-user-callerid:33] Set(“Local/1011@from-queue-000000c8;2”, “CHANNEL(language)=en”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:2] Set(“Local/1011@from-queue-000000c8;2”, “RingGroupMethod=none”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:3] Set(“Local/1011@from-queue-000000c8;2”, “__EXTTOCALL=1011”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:4] Set(“Local/1011@from-queue-000000c8;2”, “__PICKUPMARK=1011”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:5] Set(“Local/1011@from-queue-000000c8;2”, “RT=”) in new stack
[2016-06-21 10:58:00.690] WARNING[28580][C-00001e36] chan_sip.c: This function can only be used on SIP channels.
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:6] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Macro(vm,novm,DIRECTDIAL,)”) in new stack
[2016-06-21 10:58:00.690] WARNING[28580][C-00001e36] chan_sip.c: This function can only be used on SIP channels.
[2016-06-21 10:58:00.690] WARNING[28580][C-00001e36] chan_sip.c: This function can only be used on SIP channels.
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:7] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?MacroExit()”) in new stack
[2016-06-21 10:58:00.690] WARNING[28580][C-00001e36] chan_sip.c: This function can only be used on SIP channels.
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:8] Gosub(“Local/1011@from-queue-000000c8;2”, “sub-record-check,s,1(exten,1011,dontcare)”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:1] GotoIf(“Local/1011@from-queue-000000c8;2”, “29?initialized”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Goto (sub-record-check,s,10)
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:10] NoOp(“Local/1011@from-queue-000000c8;2”, “Recordings initialized”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:11] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(ARG3=dontcare)”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:12] Set(“Local/1011@from-queue-000000c8;2”, “REC_POLICY_MODE_SAVE=YES”) in new stack
[2016-06-21 10:58:00.690] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:13] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(REC_STATUS=NO)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:14] GotoIf(“Local/1011@from-queue-000000c8;2”, “5?checkaction”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Goto (sub-record-check,s,17)
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@sub-record-check:17] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?sub-record-check,exten,1”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Goto (sub-record-check,exten,1)
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:1] NoOp(“Local/1011@from-queue-000000c8;2”, “Exten Recording Check between Rached@0021673656042@27_3@141 and 1011”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:2] Set(“Local/1011@from-queue-000000c8;2”, “CALLTYPE=internal”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:3] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(CALLTYPE=)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:4] Set(“Local/1011@from-queue-000000c8;2”, “CALLEE=yes”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:5] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(CALLEE=dontcare)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:6] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?callee”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:7] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?caller”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:8] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(CALLER_PRI=):Set(CALLER_PRI=0)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:9] ExecIf(“Local/1011@from-queue-000000c8;2”, “2?Set(CALLEE_PRI=10):Set(CALLEE_PRI=0)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:10] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?caller:callee”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Goto (sub-record-check,exten,11)
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:11] Gosub(“Local/1011@from-queue-000000c8;2”, “recordcheck,1(yes,internal,1011)”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“Local/1011@from-queue-000000c8;2”, “Starting recording check against yes”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“Local/1011@from-queue-000000c8;2”, “yes”) in new stack
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Goto (sub-record-check,recordcheck,9)
[2016-06-21 10:58:00.691] VERBOSE[28580][C-00001e36] pbx.c: Executing [recordcheck@sub-record-check:9] ExecIf(“Local/1011@from-queue-000000c8;2”, “1?Return()”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [exten@sub-record-check:12] Return(“Local/1011@from-queue-000000c8;2”, “”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:9] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?macrodial”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-exten-vm,s,15)
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:15] GosubIf(“Local/1011@from-queue-000000c8;2”, “0?clrheader,1()”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-exten-vm:16] Macro(“Local/1011@from-queue-000000c8;2”, “dial-one,TtrM(auto-blkvm),1011”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:1] Set(“Local/1011@from-queue-000000c8;2”, “DEXTEN=1011”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:2] Set(“Local/1011@from-queue-000000c8;2”, “DIALSTATUS_CW=”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:3] GosubIf(“Local/1011@from-queue-000000c8;2”, “0?screen,1()”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:4] GosubIf(“Local/1011@from-queue-000000c8;2”, “0?cf,1()”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:5] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?skip1”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,8)
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:8] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?nodial”) in new stack
[2016-06-21 10:58:00.692] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:9] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?continue”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:10] Set(“Local/1011@from-queue-000000c8;2”, “EXTHASCW=”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:11] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?next1:cwinusebusy”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,12)
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:12] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?docfu:skip3”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,16)
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:16] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?next2:continue”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,17)
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:17] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?continue”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,25)
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:25] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?nodial”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:26] GosubIf(“Local/1011@from-queue-000000c8;2”, “1?dstring,1():dlocal,1()”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:1] Set(“Local/1011@from-queue-000000c8;2”, “DSTRING=”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:2] Set(“Local/1011@from-queue-000000c8;2”, “DEVICES=1011”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Return()”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(DEVICES=011)”) in new stack
[2016-06-21 10:58:00.693] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:5] Set(“Local/1011@from-queue-000000c8;2”, “LOOPCNT=1”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:6] Set(“Local/1011@from-queue-000000c8;2”, “ITER=1”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:7] Set(“Local/1011@from-queue-000000c8;2”, “THISDIAL=SIP/1011”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf(“Local/1011@from-queue-000000c8;2”, “1?zap2dahdi,1()”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Return()”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set(“Local/1011@from-queue-000000c8;2”, “NEWDIAL=”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set(“Local/1011@from-queue-000000c8;2”, “LOOPCNT2=1”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set(“Local/1011@from-queue-000000c8;2”, “ITER2=1”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set(“Local/1011@from-queue-000000c8;2”, “THISPART2=SIP/1011”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Set(THISPART2=DAHDI/1011)”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set(“Local/1011@from-queue-000000c8;2”, “NEWDIAL=SIP/1011&”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set(“Local/1011@from-queue-000000c8;2”, “ITER2=2”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?begin2”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set(“Local/1011@from-queue-000000c8;2”, “THISDIAL=SIP/1011”) in new stack
[2016-06-21 10:58:00.694] VERBOSE[28580][C-00001e36] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return(“Local/1011@from-queue-000000c8;2”, “”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?doset”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,dstring,13)
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:13] Set(“Local/1011@from-queue-000000c8;2”, “DSTRING=SIP/1011&”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:14] Set(“Local/1011@from-queue-000000c8;2”, “ITER=2”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?begin”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:16] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?Return()”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:17] Set(“Local/1011@from-queue-000000c8;2”, “DSTRING=SIP/1011”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [dstring@macro-dial-one:18] Return(“Local/1011@from-queue-000000c8;2”, “”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:27] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?nodial”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:28] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?skiptrace”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:29] GosubIf(“Local/1011@from-queue-000000c8;2”, “0?ctset,1():ctclear,1()”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [ctclear@macro-dial-one:1] NoOp(“Local/1011@from-queue-000000c8;2”, "Deleting: CALLTRACE/1011 ") in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [ctclear@macro-dial-one:2] Return(“Local/1011@from-queue-000000c8;2”, “”) in new stack
[2016-06-21 10:58:00.695] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:30] Set(“Local/1011@from-queue-000000c8;2”, “D_OPTIONS=TtrM(auto-blkvm)”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:31] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:32] ExecIf(“Local/1011@from-queue-000000c8;2”, “0?SIPAddHeader()”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:33] ExecIf(“Local/1011@from-queue-000000c8;2”, “1?Set(CHANNEL(musicclass)=none)”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:34] GosubIf(“Local/1011@from-queue-000000c8;2”, “0?qwait,1()”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:35] Set(“Local/1011@from-queue-000000c8;2”, “__CWIGNORE=TRUE”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:36] Set(“Local/1011@from-queue-000000c8;2”, “__KEEPCID=TRUE”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:37] GotoIf(“Local/1011@from-queue-000000c8;2”, “0?usegoto,1”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:38] GotoIf(“Local/1011@from-queue-000000c8;2”, “1?godial”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Goto (macro-dial-one,s,43)
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:43] Macro(“Local/1011@from-queue-000000c8;2”, “dialout-one-predial-hook,”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit(“Local/1011@from-queue-000000c8;2”, “”) in new stack
[2016-06-21 10:58:00.696] VERBOSE[28580][C-00001e36] pbx.c: Executing [s@macro-dial-one:44] Dial(“Local/1011@from-queue-000000c8;2”, “SIP/1011,TtrM(auto-blkvm)”) in new stack
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] netsock2.c: Using SIP RTP TOS bits 184
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] netsock2.c: Using SIP RTP CoS mark 5
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Audio is at 13380
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Adding codec ulaw to SDP
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Adding codec alaw to SDP
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Adding codec gsm to SDP
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Adding codec g722 to SDP
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] chan_sip.c: Reliably Transmitting (NAT) to 93.87.73.66:3000:
INVITE sip:1011@93.87.73.66:3000;rinstance=651969a588434b71 SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK3f2c7472;rport
Max-Forwards: 70
From: “Dialer” sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
Contact: sip:Rached%400021673656042%4027_3%40141@ServerIP:5060
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 INVITE
User-Agent: FPBX-12.0.69(13.4.0)
Date: Tue, 21 Jun 2016 08:58:00 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 320

v=0
o=root 65914998 65914998 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13380 RTP/AVP 0 8 3 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2016-06-21 10:58:00.710] VERBOSE[28580][C-00001e36] app_dial.c: Called SIP/1011
[2016-06-21 10:58:00.711] VERBOSE[27398][C-00001e36] app_queue.c: Local/1011@from-queue-000000c8;1 is ringing
[2016-06-21 10:58:00.810] VERBOSE[3695] chan_sip.c: Retransmitting #1 (NAT) to 93.87.73.66:3000:
INVITE sip:1011@93.87.73.66:3000;rinstance=651969a588434b71 SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK3f2c7472;rport
Max-Forwards: 70
From: “Dialer” sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
Contact: sip:Rached%400021673656042%4027_3%40141@ServerIP:5060
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 INVITE
User-Agent: FPBX-12.0.69(13.4.0)
Date: Tue, 21 Jun 2016 08:58:00 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 320

v=0
o=root 65914998 65914998 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13380 RTP/AVP 0 8 3 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

**[2016-06-21 10:58:00.855] VERBOSE[3695] chan_sip.c: **
<— SIP read from UDP:93.87.73.66:3000 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK3f2c7472;rport=5060
Contact: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71;tag=5f58d869
From: "Dialer"sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 INVITE
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

<------------->
[2016-06-21 10:58:00.855] VERBOSE[3695] chan_sip.c: — (9 headers 0 lines) —
[2016-06-21 10:58:00.855] VERBOSE[3695][C-00001e36] sip/route.c: sip_route_dump: route/path hop: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
[2016-06-21 10:58:00.855] VERBOSE[28580][C-00001e36] app_dial.c: SIP/1011-0000048a is ringing
[2016-06-21 10:58:00.855] VERBOSE[27398][C-00001e36] app_queue.c: Local/1011@from-queue-000000c8;1 is ringing
**[2016-06-21 10:58:00.855] VERBOSE[3695] chan_sip.c: **
<— SIP read from UDP:93.87.73.66:3000 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK3f2c7472;rport=5060
Contact: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71;tag=5f58d869
From: "Dialer"sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 INVITE
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

<------------->
[2016-06-21 10:58:00.855] VERBOSE[3695] chan_sip.c: — (9 headers 0 lines) —
[2016-06-21 10:58:00.855] VERBOSE[3695][C-00001e36] sip/route.c: sip_route_dump: route/path hop: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
[2016-06-21 10:58:00.855] VERBOSE[28580][C-00001e36] app_dial.c: SIP/1011-0000048a is ringing
[2016-06-21 10:58:03.301] VERBOSE[3695] chan_sip.c: Reliably Transmitting (NAT) to 93.87.73.66:3000:
OPTIONS sip:1011@93.87.73.66:3000;rinstance=651969a588434b71 SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK10451f15;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@ServerIP;tag=as2fefbe95
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
Contact: sip:Unknown@ServerIP:5060
Call-ID: 57fa9c8407fb346b10cdf41a266b1490@ServerIP:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-12.0.69(13.4.0)
Date: Tue, 21 Jun 2016 08:58:03 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

[2016-06-21 10:58:03.450] VERBOSE[3695] chan_sip.c:
<— SIP read from UDP:93.87.73.66:3000 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK10451f15;rport=5060
Contact: sip:93.87.73.66:3000
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71;tag=d205d01a
From: "Unknown"sip:Unknown@ServerIP;tag=as2fefbe95
Call-ID: 57fa9c8407fb346b10cdf41a266b1490@ServerIP:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

<------------->
[2016-06-21 10:58:03.450] VERBOSE[3695] chan_sip.c: — (12 headers 0 lines) —
[2016-06-21 10:58:03.450] VERBOSE[3695] chan_sip.c: Really destroying SIP dialog ‘57fa9c8407fb346b10cdf41a266b1490@ServerIP:5060’ Method: OPTIONS
[2016-06-21 10:58:03.450] VERBOSE[3695] chan_sip.c:
<— SIP read from UDP:93.87.73.66:3000 —>

<------------->
[2016-06-21 10:58:03.870] VERBOSE[3695] chan_sip.c:
<— SIP read from UDP:93.87.73.66:11504 —>

<------------->
**[2016-06-21 10:58:04.654] VERBOSE[3695] chan_sip.c: **
<— SIP read from UDP:93.87.73.66:3000 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK3f2c7472;rport=5060
Contact: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71;tag=5f58d869
From: "Dialer"sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 236

v=0
o=- 1 2 IN IP4 93.87.73.66
s=CounterPath eyeBeam 1.5
c=IN IP4 93.87.73.66
t=0 0
m=audio 3612 RTP/AVP 0 8 101
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=x-rtp-session-id:0AB26436120E4AD0BEBEEE264A7968A7
<------------->
[2016-06-21 10:58:04.654] VERBOSE[3695] chan_sip.c: — (11 headers 10 lines) —
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Found RTP audio format 0
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Found RTP audio format 8
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Found RTP audio format 101
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Found audio description format telephone-event for ID 101
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Capabilities: us - (ulaw|alaw|gsm|g722), peer - audio=(ulaw|alaw)/video=(nothing)/text=(nothing), combined - (ulaw|alaw)
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Peer audio RTP is at port 93.87.73.66:3612
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] sip/route.c: sip_route_dump: route/path hop: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71
[2016-06-21 10:58:04.654] VERBOSE[3695][C-00001e36] chan_sip.c: Transmitting (NAT) to 93.87.73.66:3000:
ACK sip:1011@93.87.73.66:3000;rinstance=651969a588434b71 SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK6c5c8e75;rport
Max-Forwards: 70
From: “Dialer” sip:Rached%400021673656042%4027_3%40141@ServerIP;tag=as5315bd90
To: sip:1011@93.87.73.66:3000;rinstance=651969a588434b71;tag=5f58d869
Contact: sip:Rached%400021673656042%4027_3%40141@ServerIP:5060
Call-ID: 6408233662f25de6272ce73147908dec@ServerIP:5060
CSeq: 102 ACK
User-Agent: FPBX-12.0.69(13.4.0)
Content-Length: 0

[2016-06-21 10:58:04.654] VERBOSE[28580][C-00001e36] app_dial.c: SIP/1011-0000048a answered Local/1011@from-queue-000000c8;2

As I remarked, in the 3-4 s delay in which the extension is ringing ( % Asterisk server), there is no log , no feedback from agent Softphone, Is that normal ?

I really don’t know weather the cause is from agent softphone not sending answering feedback or the problem with Asterisk server not treating/showing softphone feedback in real time!!

Please have you any ideas about that ??
Thanks in advance.

david551 · June 21, 2016, 8:37pm

You have a round trip time of significantly more than 100ms, which is not good, but the multi-second delay between ringing and answer appears to be entirely at the remote end,

wilwil · June 21, 2016, 9:23pm

Is this configurable somewhere in Asterisk ? How should I do to reduce this time ??

wilwil · June 21, 2016, 9:27pm

How can I debug this in the remote end (I use EyeBeam as softphone) to be sure that the problem is not caused by Server Box. ?

david551 · June 21, 2016, 9:59pm

No. It is a consequence of the network path to the phone. Unless you are overloading a local router, that probably means changing ISPs at one or both ends.

(There are options that can help deal with local routers, but if you knew enough about your router to make use of them, you would probably already have found them.)

david551 · June 21, 2016, 10:06pm

For eyebeam itself, consult the documentation, or use the support services provided by Counterpath. For the rest of system local to eyebeam you haven’t provided enough information to even guess at what is possible.

Page 40 of http://www.counterpath.com/assets/product_documents/eyeBeam_1.5_User_Guide.pdf seems to be the only information published on diagnostics in eyebeam and that page doesn’t provide any detail of what is logged.

david551 · June 21, 2016, 10:27pm

As eyebeam is a Windows softphone, you can run Wireshark on the remote system to get a packet trace.

However, the fact that you get the response to the OPTIONS before the answered makes me think that the answered could not have been sent until after Asterisk sent OPTIONS. (OPTIONS Is used by the qualify option, to test connectivity and round trip time.)

wilwil · June 22, 2016, 1:35am

For remote end I did a full debug generated by eyeBeam soft-phone: and here is the result (it’s similar to Asterisk debug log but has some different sides):
This is a call transmitted from queue also . And “Auto-Answer” feature activated in softphone .

ime | Type | Subsystem | Message | Function

" |
[16-06-22]00:20:39.360 | Info (debug) RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSPORT | “incoming from: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | "Checking if SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) is for me" |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | “Checking rule…” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | "Matching rule for INVITE sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Max-Forwards: 70
Contact: sip:Rached%400021655534567%4027_3%40141@ServerIP:5060
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
From: ““Dialer”” sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Content-Type: application/sdp
Date: Tue, 21 Jun 2016 22:20:46 GMT
Supported: replaces, timer
User-Agent: FPBX-12.0.69(13.4.0)
Content-Length: 322

v=0
o=root 525180867 525180867 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13044 RTP/AVP 0 8 3 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
" |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | “Match!” |
[16-06-22]00:20:45.170 | Info (debug) RESIP | “Helper::makeResponse(SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) code=100 reason=” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | “Adding timer: Timer Trying tid=0d0b3e8e ms=80” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:TRANSACTION | "Send to TU: TU: DialogUsageManager size=0 INVITE sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Max-Forwards: 70
Contact: sip:Rached%400021655534567%4027_3%40141@ServerIP:5060
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
From: ““Dialer”” sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Content-Type: application/sdp
Date: Tue, 21 Jun 2016 22:20:46 GMT
Supported: replaces, timer
User-Agent: FPBX-12.0.69(13.4.0)
Content-Length: 322

v=0
o=root 525180867 525180867 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13044 RTP/AVP 0 8 3 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
" |
[16-06-22]00:20:45.170 | Info (debug) RESIP | “SipMessage::getContents: application/sdp” |
[16-06-22]00:20:45.170 | Info (debug) RESIP:DUM | "Decrypted message:0657D750
" |
[16-06-22]00:20:45.171 | Info (more) RESIP:DUM | “Got: SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire)” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “DialogUsageManager::processRequest: SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire)” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "********** Generated Local Tag *********** " |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Looking for dialogSet: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-8647ce09 in map:” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “[1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 → 063EB318]” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "********** Generated Local Tag *********** " |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “********** Generated Local Tag *********** " |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | " ************* Created DialogSet(UAS) – 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c*************” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "*********** Calling AppDialogSetFactory " |
[16-06-22]00:20:45.171 | Info (debug) CCM | " [URI:1001@ServerDomainName]" | sua::CSIPAccess::OnIncomingInvite
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | " Adding DialogSet *****" |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Before: [1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 → 063EB318]” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “After: Req[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c → 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 → 063EB318]” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | " Generated Local Tag *********** " |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “DialogId::DialogId: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-9b642f08-as709ad49a” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "Creating a new Dialog from msg: INVITE sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Max-Forwards: 70
Contact: sip:Rached%400021655534567%4027_3%40141@ServerIP:5060
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Content-Type: application/sdp
Date: Tue, 21 Jun 2016 22:20:46 GMT
Supported: replaces, timer
User-Agent: FPBX-12.0.69(13.4.0)
Content-Length: 322

v=0
o=root 525180867 525180867 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13044 RTP/AVP 0 8 3 9 101
a=fmtp:101 0-16
a=maxptime:150
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
" |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “UAS dialog ID creation, DS: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “DialogId::DialogId: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c-as709ad49a” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “************** Created Dialog as UAS **************” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "mRemoteNameAddr: "“Dialer”“sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “mLocalNameAddr: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “mLocalContact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “mRemoteTarget: sip:Rached%400021655534567%4027_3%40141@ServerIP:5060” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Dialog::Dialog 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c-as709ad49a” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | "### Calling CreateAppDialog ### INVITE sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c SIP/2.0
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Max-Forwards: 70
Contact: sip:Rached%400021655534567%4027_3%40141@ServerIP:5060
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Content-Type: application/sdp
Date: Tue, 21 Jun 2016 22:20:46 GMT
Supported: replaces, timer
User-Agent: FPBX-12.0.69(13.4.0)
Content-Length: 322

v=0
o=root 525180867 525180867 IN IP4 ServerIP
s=Asterisk PBX 13.4.0
c=IN IP4 ServerIP
t=0 0
m=audio 13044 RTP/AVP 0 8 3 9 101
a=fmtp:101 0-16
a=maxptime:150
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
" |
[16-06-22]00:20:45.171 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPIncomingCall::OnCreateAppDialog
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Dialog::dispatch: SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire)” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Association added for [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “Dialog::dispatch – Created new server invite sessionSipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire)” |
[16-06-22]00:20:45.171 | Info (debug) RESIP:DUM | “^^^ InviteSession::InviteSession 063E8040” |
[16-06-22]00:20:45.171 | Info (debug) RESIP | “Got sdp
" |
[16-06-22]00:20:45.171 | Info (more) RESIP:DUM | “Transition UAS_Start → UAS_Offer” |
[16-06-22]00:20:45.172 | Info (debug) CCM | “SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.172 | Info (more) CCM | “[UAS][state:ECallState_Undefined][sdp-state:ESDPState_Undefined] ← [event:onNewSession (UAS)] [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.172 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::onOffer
[16-06-22]00:20:45.172 | Info (debug) CCM | “SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.172 | Info (more) CCM | “[UAS][state:EUASNew_Undefined][sdp-state:ESDPState_Undefined] ← [event:onOffer] [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.172 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPIncomingCall::OnNewUASSession
[16-06-22]00:20:45.172 | Info (debug) AbstractPhone | “[1001@ServerDomainName]::OnIncomingCallReceived” | AbPhone::CAccount::CCCMSink::OnIncomingCall
[16-06-22]00:20:45.172 | Info (debug) AbstractPhone | “[1001@ServerDomainName]::OnIncomingCallReplaces” | AbPhone::CAccount::CCCMSink::OnIncomingCallReplaces
[16-06-22]00:20:45.172 | Info (debug) AbstractPhone | “StartAudioSubsystem” | AbPhone::CAbstractPhone::StartAudioSubsystem
[16-06-22]00:20:45.174 | Info (more) Audio | “Active tuning wizard profile (289) set audio out mute=false” | sua::CTuningWizard::SetTuningProfileAudioOutMute
[16-06-22]00:20:45.174 | Info (debug) Audio | “StartAudio entry point” | sua::CAudioManager::StartAudio
[16-06-22]00:20:45.174 | Info (min) Utilities | “Detected CPU [Intel(R) Pentium(R) CPU P6200 @ 2.13GHz]” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:45.174 | Info (more) Utilities | “Detected frequency: 2130” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:45.174 | Info (debug) Utilities | “Adding timer8834, m_cTimers.size() 5” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.174 | Info (min) Utilities | “Detected CPU [Intel(R) Pentium(R) CPU P6200 @ 2.13GHz]” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:45.174 | Info (more) Utilities | “Detected frequency: 2130” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:45.176 | Info (debug) Audio | “pre-waveInOpen, where channels=1, sample rate=16000, device ID=0, block size=160” | sua::CAudioDeviceWaveInInstance::Open
[16-06-22]00:20:45.188 | Info (debug) Audio | “waveInOpen succeeded” | sua::CAudioDeviceWaveInInstance::Open
[16-06-22]00:20:45.188 | Info (debug) Utilities | “Adding timer8845, m_cTimers.size() 6” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.190 | Info (more) Audio | “Device supports 8000 Hz” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.190 | Info (more) Audio | “Device supports 16000 Hz” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.190 | Info (more) Audio | “Device supports 22050 Hz” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.190 | Info (more) Audio | “Device supports 44100 Hz” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.190 | Info (more) Audio | “Device supports 48000 Hz” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.190 | Info (debug) Audio | “pre-waveOutOpen, where channels=1, sample rate=16000, device ID=0, block size=160” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.196 | Info (debug) Audio | “waveOutOpen succeeded” | sua::CAudioDeviceWaveOutInstance::Open
[16-06-22]00:20:45.196 | Info (more) Audio | “Audio started, where instance ID=8836, Out: Speakers (Logitech USB Headset)” | sua::CAudioManager::StartAudio
[16-06-22]00:20:45.196 | Info (debug) AbstractPhone | “Opening media port (104910344)” | AbPhone::CCallMediaPort::CCallMediaPort
[16-06-22]00:20:45.196 | Info (debug) AbstractPhone | “Putting audio on hold in media port (104910344)” | AbPhone::CCallMediaPort::PutAudioOnHold
[16-06-22]00:20:45.196 | Info (debug) AbstractPhone | “Putting video on hold in media port (104910344)” | AbPhone::CCallMediaPort::PutVideoOnHold
[16-06-22]00:20:45.196 | Info (more) Audio | “Handling device wrap” | sua::CAudioDeviceWaveOutInstance::GetUnplayedSamples
[16-06-22]00:20:45.196 | Info (debug) CCM | “Permitting all codecs. [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPIncomingCall::PrepareMedia
[16-06-22]00:20:45.196 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPCall::PrepareMedia
[16-06-22]00:20:45.196 | Info (more) CCM | “[UAS][state:EUASNew_Undefined][sdp-state:ESDPOfferReceived] ← [event:PrepareMedia] [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.196 | Info (more) Media | “Media session created, where session ID=8857” | sua::CMediaSession::CMediaSession
[16-06-22]00:20:45.196 | Info (debug) Media | “Creating answer for media session, where session ID=8857” | sua::CMediaSession::MakeAnswer
[16-06-22]00:20:45.196 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.196 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.196 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.196 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.196 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.197 | Info (debug) Media | “Media type session created, where media type session ID=8859, where media type=audio, where media type=audio, where media transport=RTP/AVP, where force describe well known codecs=false” | sua::CMediaTypeAudioVideoRTP::CMediaTypeAudioVideoRTP
[16-06-22]00:20:45.197 | Info (debug) Media | “Creating media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio, where copying from existing media type branch ID=N/A” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP
[16-06-22]00:20:45.197 | Info (debug) Media | “Received remote offer on media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::ValidateRemoteOffer
[16-06-22]00:20:45.197 | Info (debug) Media | “Waiting for higher level to accept remote offer for media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::ValidateRemoteOffer
[16-06-22]00:20:45.198 | Info (debug) Media | “Media type has validated the remote SDP offer, where session ID=8857” | sua::CMediaSession::OnMediaTypeRemoteOfferValidated
[16-06-22]00:20:45.198 | Info (debug) Media | “All media types have validated the remote SDP offer so wait for higher level to accept media, where session ID=8857” | sua::CMediaSession::OnMediaTypeRemoteOfferValidated
[16-06-22]00:20:45.198 | Info (debug) AbstractPhone | “OnMediaPendingChangesOffered” | AbPhone::CCall::CCallSessionSink::OnMediaPendingChangesOffered
[16-06-22]00:20:45.198 | Info (debug) Media | “RTP for media type session setup, where media type session ID=8859, where media type=audio, where hint count=2, where encrypted=false, where crypto count=0” | sua::CMediaTypeAudioVideoRTP::SetupRTP
[16-06-22]00:20:45.200 | Error (more) Transport | “Unable to set DSCP/TOS value on socket as magic registry key was not set, see Microsoft support Article ID 248611, where socket type=UDP, where socket instance ID=8867” | sua::CTransportSocketFactory::CUDPSocket::SetTaggedQOS
[16-06-22]00:20:45.200 | Error (more) Transport | “Unable to set DSCP/TOS value on socket as magic registry key was not set, see Microsoft support Article ID 248611, where socket type=UDP, where socket instance ID=8868” | sua::CTransportSocketFactory::CUDPSocket::SetTaggedQOS
[16-06-22]00:20:45.200 | Info (more) STUN | “STUN: Requested FW Address discovery using STUN server: ServerIP:3478” | sua::CFirewallAddressDiscovery::CFirewallAddressDiscovery
[16-06-22]00:20:45.200 | Info (debug) Utilities | “Adding timer8874, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.200 | Info (more) STUN | “STUN: Requested FW Address discovery using STUN server: ServerIP:3478” | sua::CFirewallAddressDiscovery::CFirewallAddressDiscovery
[16-06-22]00:20:45.200 | Info (debug) Utilities | “Adding timer8877, m_cTimers.size() 8” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.208 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPIncomingCall::SendProvisional
[16-06-22]00:20:45.208 | Info (more) CCM | “[UAS][state:EUASNew_WaitForMMAnswerOrOffer][sdp-state:ESDPOfferReceived] ← [event:SendProvisional] [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.208 | Info (more) RESIP:DUM | “UAS_Offer: provisional(180)” |
[16-06-22]00:20:45.208 | Info (more) RESIP:DUM | “Transition UAS_Offer → UAS_EarlyOffer” |
**[16-06-22]00:20:45.208 | Info (debug) RESIP | “Helper::makeResponse(SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) code=180 reason=” | **
[16-06-22]00:20:45.208 | Info (debug) RESIP:DUM | "Dialog::makeResponse: SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Content-Length: 0

" |
[16-06-22]00:20:45.208 | Info (debug) RESIP:TRANSACTION | “Adding application timer: DumTimeout::Retransmit1xx INVITE: 118 UAS_EarlyOffer ADDR=sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c PEER=”“Dialer”“sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a: duration=60 seq=102” |
[16-06-22]00:20:45.208 | Info (debug) RESIP:DUM | “Looking for dialogSet: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c in map:” |
[16-06-22]00:20:45.208 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c → 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 → 063EB318]” |
[16-06-22]00:20:45.208 | Info (debug) RESIP:DUM | "SEND: SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

" |
[16-06-22]00:20:45.208 | Info (debug) RESIP | “SEND: SipResp: 180 tid=0d0b3e8e cseq=INVITE contact=1001@192.168.1.103:48244 / 102 from(tu)” |
[16-06-22]00:20:45.224 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.236 | Info (more) AbstractPhone | “SetEventSink” | AbPhone::CCall::SetEventSink
[16-06-22]00:20:45.236 | Info (debug) Media | “Commit media session called, where session ID=8857” | sua::CMediaSession::CommitPendingMedia
[16-06-22]00:20:45.236 | Info (debug) Media | “Actually making answer for media session, where session ID=8857” | sua::CMediaSession::ActualMakeAnswer
[16-06-22]00:20:45.236 | Info (debug) Media | “Making answer for media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::MakeAnswer
[16-06-22]00:20:45.236 | Info (debug) Media | “Making answer delayed until RTP ready on media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::MakeAnswer
[16-06-22]00:20:45.236 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPIncomingCall::AllowCall
[16-06-22]00:20:45.236 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPCall::AllowCall
[16-06-22]00:20:45.236 | Info (more) CCM | “[UAS][state:EUASNew_WaitForMMAnswerOrOffer][sdp-state:ESDPOfferReceived] ← [event:AllowCall] [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:45.236 | Info (debug) CCM | " [1001@ServerDomainName ← Rached@0021655534567@27_3@141@ServerIP]" | sua::CSIPIncomingCall::InternalShutdown
[16-06-22]00:20:45.236 | Info (debug) AbstractPhone | “StartAudioSubsystem” | AbPhone::CAbstractPhone::StartAudioSubsystem
[16-06-22]00:20:45.236 | Info (more) AbstractPhone | “EnableAudio” | AbPhone::CCall::EnableAudio2
[16-06-22]00:20:45.236 | Info (debug) AbstractPhone | “Putting audio off hold in media port (104910344)” | AbPhone::CCallMediaPort::PutAudioOffHold
[16-06-22]00:20:45.255 | Info (debug) AbstractPhone | “[1001@ServerDomainName]::OnIncomingCallTerminated” | AbPhone::CAccount::CCCMSink::OnIncomingCallTerminated
[16-06-22]00:20:45.255 | Info (debug) AbstractPhone | “StopAudioSubsystem” | AbPhone::CAbstractPhone::StopAudioSubsystem
[16-06-22]00:20:45.272 | Info (debug) RESIP:TRANSPORT | “Looked up source for destination: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] → [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] sent-by=ServerIP sent-port=5060” |
[16-06-22]00:20:45.272 | Info (debug) RESIP:TRANSPORT | "Transmitting to [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

" |
[16-06-22]00:20:45.272 | Info (debug) RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.310 | Info (debug) RESIP:TRANSPORT | “incoming from: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.313 | Info (debug) RESIP:TRANSPORT | “Looked up source for destination: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] → [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] sent-by=ServerIP sent-port=5060” |
[16-06-22]00:20:45.313 | Info (debug) RESIP:TRANSPORT | "Transmitting to [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]SIP/2.0 180 Ringing
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 0

wilwil · June 22, 2016, 1:44am

" |
[16-06-22]00:20:45.313 | Info (debug) RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:45.344 | Info (debug) Audio | “Allocated in audio device: 320” | sua::CAudioDeviceWaveOutInstance::GetUnusedWaveHdr
[16-06-22]00:20:45.451 | Info (debug) Utilities | “Removing timer 8874, m_cTimers.size() 7” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:45.451 | Info (debug) Utilities | “Removing timer 8877, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:45.452 | Info (debug) Utilities | “Adding timer8879, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.452 | Info (debug) Utilities | “Adding timer8880, m_cTimers.size() 8” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.954 | Info (debug) Utilities | “Removing timer 8879, m_cTimers.size() 7” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:45.954 | Info (debug) Utilities | “Removing timer 8880, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:45.955 | Info (debug) Utilities | “Adding timer8881, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:45.955 | Info (debug) Utilities | “Adding timer8882, m_cTimers.size() 8” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:46.956 | Info (debug) Utilities | “Removing timer 8881, m_cTimers.size() 7” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:46.956 | Info (debug) Utilities | “Removing timer 8882, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:46.957 | Info (debug) Utilities | “Adding timer8883, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:46.957 | Info (debug) Utilities | “Adding timer8884, m_cTimers.size() 8” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:47.958 | Info (debug) Utilities | “Removing timer 8883, m_cTimers.size() 7” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:47.958 | Info (debug) Utilities | “Removing timer 8884, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:47.959 | Info (debug) Utilities | “Adding timer8885, m_cTimers.size() 7” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:47.959 | Info (debug) Utilities | “Adding timer8886, m_cTimers.size() 8” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:48.318 | Info (debug) Utilities | “Removing timer 8731, m_cTimers.size() 7” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:48.319 | Info (debug) CCM | “Re-trying to SUBSCRIBE[1001@ServerDomainName -> 1001@ServerDomainName]” | sua::CSIPClientSubscriptionWatcher::OnTimer
[16-06-22]00:20:48.319 | Info (debug) CCM | “[1001@ServerDomainName -> 1001@ServerDomainName]” | sua::CSIPClientSubscriptionSession::StartSubscription
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “BaseCreator::makeInitialRequest: 0641F1C8” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | " ************* Created DialogSet(UAC) – 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69*************" |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “************* Adding DialogSet ***************” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “Before: [0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318]” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “After: [0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “Looking for dialogSet: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 in map:” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.319 | Info (debug) RESIP:DUM | "SEND: SUBSCRIBE sip:1001@ServerDomainName SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-c9467d31d73a3b6a-1–d87543-;rport
Max-Forwards: 70
Contact: sip:1001
To: ""Agent1""sip:1001@ServerDomainName
From: ""Agent1""sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 1 SUBSCRIBE
Expires: 300
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Event: message-summary
Content-Length: 0

" |
[16-06-22]00:20:48.319 | Info (debug) RESIP:TRANSACTION | "Adding application timer: " |
[16-06-22]00:20:48.413 | Info (more) RESIP:DUM | “Got a DumFeatureMessage06574BE0” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | "contact 192.168.1.103:48244 found for the request SUBSCRIBE sip:1001@ServerDomainName SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-c9467d31d73a3b6a-1–d87543-;rport
Max-Forwards: 70
Contact: sip:1001
To: ""Agent1""sip:1001@ServerDomainName
From: ""Agent1""sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 1 SUBSCRIBE
Expires: 300
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Event: message-summary
Content-Length: 0

" |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “Looking for dialogSet: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 in map:” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “DialogId::DialogId: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69-” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “Looking for dialogSet: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 in map:” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “findDialog: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69- in []” |
[16-06-22]00:20:48.414 | Info (debug) RESIP:DUM | “Using outbound proxy: sip:1001@ServerDomainName;lr -> SipReq: SUBSCRIBE 1001@ServerDomainName tid=c9467d31d73a3b6a cseq=SUBSCRIBE contact=1001@192.168.1.103:48244 / 1 from(tu)” |
[16-06-22]00:20:48.517 | Info (debug) RESIP:TRANSACTION | “Adding timer: Timer F tid=c9467d31d73a3b6a ms=32000” |
[16-06-22]00:20:48.517 | Info (debug) RESIP:DNS | “DnsResult::lookup sip:1001@ServerDomainName;lr” |
[16-06-22]00:20:48.518 | Info (more) CCM | “DSCP marking is set for SIP or DNS signaling socket, where socket=3204, where transport type=1, where resip file is W:\HEAD\SUA\Library\sipfoundry\main\contrib\ares\ares_process.c, where resip line # is 706, where DSCP value=40” | sua::CCMAfterSocketCreationFuncPtr
[16-06-22]00:20:48.572 | Info (debug) RESIP:DNS | “no TTL to cache” |
[16-06-22]00:20:48.672 | Info (more) CCM | “DSCP marking is set for SIP or DNS signaling socket, where socket=3204, where transport type=1, where resip file is W:\HEAD\SUA\Library\sipfoundry\main\contrib\ares\ares_process.c, where resip line # is 706, where DSCP value=40” | sua::CCMAfterSocketCreationFuncPtr
[16-06-22]00:20:48.684 | Info (debug) RESIP:DNS | “no TTL to cache” |
[16-06-22]00:20:48.687 | Info (debug) RESIP:DNS | “no TTL to cache” |
[16-06-22]00:20:48.803 | Info (debug) RESIP:DNS | “no TTL to cache” |
[16-06-22]00:20:48.901 | Info (debug) RESIP:DNS | “tranforming records” |
[16-06-22]00:20:48.902 | Info (debug) RESIP:TRANSACTION | “Adding timer: Timer E1 tid=c9467d31d73a3b6a ms=500” |
[16-06-22]00:20:48.906 | Info (debug) RESIP:TRANSPORT | “Looked up source for destination: [ V4 ServerIP:5060 UDP target domain=ServerDomainName connectionId=0 ] -> [ V4 192.168.1.103:0 UDP target domain=ServerDomainName connectionId=0 ] sent-by= sent-port=0” |
[16-06-22]00:20:48.906 | Info (debug) RESIP:TRANSPORT | “findTransport([ V4 192.168.1.103:0 UDP target domain=ServerDomainName connectionId=0 ])” |
[16-06-22]00:20:48.906 | Info (debug) RESIP:TRANSPORT | “findTransport (any port, any interface) => Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ]” |
[16-06-22]00:20:48.906 | Info (debug) RESIP:TRANSPORT | "Transmitting to [ V4 ServerIP:5060 UDP target domain=ServerDomainName received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.103:0 UDP target domain=ServerDomainName connectionId=0 ]SUBSCRIBE sip:1001@ServerDomainName SIP/2.0
Via: SIP/2.0/UDP 192.168.1.103:48244;branch=z9hG4bK-d87543-c9467d31d73a3b6a-1–d87543-;rport
Max-Forwards: 70
Contact: sip:1001@192.168.1.103:48244
To: ""Agent1""sip:1001@ServerDomainName
From: ""Agent1""sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 1 SUBSCRIBE
Expires: 300
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Event: message-summary
Content-Length: 0

" |
[16-06-22]00:20:48.906 | Info (debug) RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 ServerIP:5060 UDP target domain=ServerDomainName received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:48.946 | Info (debug) RESIP:TRANSPORT | “incoming from: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:48.946 | Info (debug) RESIP:DNS | “Whitelisting ServerDomainName(1): ServerIP” |
[16-06-22]00:20:48.946 | Info (debug) RESIP:DNS | “updating an existing vip: ServerIP with ServerIP” |
[16-06-22]00:20:48.946 | Info (debug) RESIP:TRANSACTION | "Send to TU: TU: DialogUsageManager size=0 SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.103:48244;branch=z9hG4bK-d87543-c9467d31d73a3b6a-1–d87543-;received=192.168.1.103;rport=48244
To: ""Agent1""sip:1001@ServerDomainName;tag=as02b4f547
From: ““Agent1"“sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 1 SUBSCRIBE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Server: FPBX-12.0.69(13.4.0)
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=”“asterisk””, nonce=”"7d7a2268""
Content-Length: 0

" |
[16-06-22]00:20:48.946 | Info (debug) RESIP:TRANSACTION | “Adding timer: Timer K tid=c9467d31d73a3b6a ms=5000” |
[16-06-22]00:20:48.947 | Info (more) RESIP:DUM | “Got: SipResp: 401 tid=c9467d31d73a3b6a cseq=SUBSCRIBE / 1 from(wire)” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “Looking for dialogSet: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 in map:” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “DialogUsageManager::processResponse: SipResp: 401 tid=c9467d31d73a3b6a cseq=SUBSCRIBE / 1 from(wire)” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “ClientAuthManager::RealmState::handleAuth: 037895A0 Digest algorithm=MD5,realm=”“asterisk”",nonce="“7d7a2268"” is proxy: 0" |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “ClientAuthManager::RealmState::transition from invalid to current” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “Didn’t find credential for realm: asterisk realm=ServerDomainName user=1001” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “Produced response to digest challenge for UserProfile: ““Agent1"“sip:1001@ServerDomainName[realm=ServerDomainName user=1001]” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “about to re-send request with digest credentials” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “Looking for dialogSet: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 in map:” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | " Add auth, 037895A0 in response to: Digest algorithm=MD5,realm=”“asterisk””,nonce=”“7d7a2268"”" |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “ClientAuthManager::RealmState::addAuthentication, proxy: 0 Digest username=”“1001"”,realm="“asterisk”",nonce="“7d7a2268"”,uri="“sip:1001@ServerDomainName”",response="“ecd8b1db1574a687783cd54152cae973"”,algorithm=MD5" |
[16-06-22]00:20:48.947 | Info (debug) RESIP:DUM | “SEND: SUBSCRIBE sip:1001@ServerDomainName SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-9c19b41a821a7c2b-1–d87543-;rport
Max-Forwards: 70
Contact: sip:1001@192.168.1.103:48244
To: ““Agent1"“sip:1001@ServerDomainName
From: ““Agent1"“sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 2 SUBSCRIBE
Expires: 300
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Authorization: Digest username=”“1001"”,realm=”“asterisk””,nonce=”“7d7a2268"”,uri=”“sip:1001@ServerDomainName””,response=”“ecd8b1db1574a687783cd54152cae973"”,algorithm=MD5
Event: message-summary
Content-Length: 0

" |
[16-06-22]00:20:48.947 | Info (debug) RESIP:TRANSACTION | "Adding application timer: " |
[16-06-22]00:20:48.961 | Info (debug) Utilities | “Removing timer 8885, m_cTimers.size() 6” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:48.961 | Info (debug) Utilities | “Removing timer 8886, m_cTimers.size() 5” | sua::CTimerManager::CancelTimer
[16-06-22]00:20:48.961 | Info (debug) STUN | “NAT-IP::Timed-out” | sua::CFirewallAddressDiscovery::OnTimer
[16-06-22]00:20:48.961 | Info (more) STUN | “STUN: NOK FW Address discovery!” | sua::CFirewallAddressDiscovery::CompleteAsFailure
[16-06-22]00:20:48.961 | Info (debug) STUN | “NAT-IP::Timed-out” | sua::CFirewallAddressDiscovery::OnTimer
[16-06-22]00:20:48.961 | Info (more) STUN | “STUN: NOK FW Address discovery!” | sua::CFirewallAddressDiscovery::CompleteAsFailure
[16-06-22]00:20:48.961 | Info (more) STUN | “ICE: Server registration: , username=VuMd6jeV, password=/OqnMKvY” | sua::CSTUNClient::RegisterForIncomingRequests
[16-06-22]00:20:48.962 | Info (more) RTP | "ICE: The following My Addresses have been collected: Default RTP: 192.168.1.103:20412; Default RTCP: 192.168.1.103:20413; 1. RTP: 192.168.1.103:20412,un=VuMd6jeV,p= /OqnMKvY; 1. RTCP: 192.168.1.103:20413,un=VuMd6jeV,p= /OqnMKvY; " | sua::CICEMyAddresses::LogMyAddressesCollection
[16-06-22]00:20:48.962 | Info (debug) Media | “RTP session open for media type session, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::OnRTPSessionOpened
[16-06-22]00:20:48.962 | Info (more) RTP | "ICE: The following Her Addresses (remote) will be tested for reachability: Default RTP: ServerIP:13044; Default RTCP: ServerIP:13045; " | sua::CICEHerAddresses::LogHerAddressesCollection
[16-06-22]00:20:48.962 | Info (debug) Utilities | “Adding timer8893, m_cTimers.size() 6” | sua::CTimerManager::CreateTimer
[16-06-22]00:20:48.962 | Info (debug) Media | “Notifying higher layer of new outgoing media for media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio, where outgoing stream ID=8891” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::UpdateDependencies
[16-06-22]00:20:48.962 | Info (debug) Media | “Notifying higher layer of answer for media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::ActualMakeAnswer
[16-06-22]00:20:48.962 | Info (more) RTP | “RTP SENDING: Starting (first one) to send RTCP packages to address: ServerIP:13045” | sua::CRTPDestination::SendRTCPCompoundPackage
[16-06-22]00:20:48.962 | Info (debug) Media | “Media type has prepared an answer for the SDP session, where session ID=8857” | sua::CMediaSession::OnMediaTypeAnswerReady
[16-06-22]00:20:48.962 | Info (debug) Media | “All media types have prepared an answer for the SDP session so the answer is now commited, where session ID=8857” | sua::CMediaSession::OnMediaTypeAnswerReady
[16-06-22]00:20:48.962 | Info (more) CCM | “[UAS][state:EUASNew_CallAllowed][sdp-state:ESDPOfferReceived] <- [event:OnAnswer] [1001@ServerDomainName <- Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:48.962 | Info (more) RESIP:DUM | “UAS_EarlyOffer: provideAnswer” |
[16-06-22]00:20:48.962 | Info (more) RESIP:DUM | “Transition UAS_EarlyOffer -> UAS_EarlyProvidedAnswer” |
[16-06-22]00:20:48.962 | Info (more) RESIP:DUM | “UAS_EarlyProvidedAnswer: accept(200)” |
[16-06-22]00:20:48.962 | Info (more) RESIP:DUM | “Transition UAS_EarlyProvidedAnswer -> UAS_Accepted” |
[16-06-22]00:20:48.962 | Info (debug) RESIP | “Helper::makeResponse(SipReq: INVITE 1001@192.168.1.103:48244 tid=0d0b3e8e cseq=INVITE contact=Rached@0021655534567@27_3@141@ServerIP:5060 / 102 from(wire) code=200 reason=” |
[16-06-22]00:20:48.962 | Info (debug) AbstractPhone | “OnNewOutgoingMedia” | AbPhone::CCall::CCallSessionSink::OnNewOutgoingMedia
[16-06-22]00:20:48.962 | Info (debug) Media | “Installing outgoing stream data handler for media type branch, where media branch ID=8860, where media type session ID=8859, where media type=audio, where media setup handle=8890” | sua::CMediaTypeAudioVideoRTP::CBranchedMediaTypeAudioVideoRTP::GetOutgoingAudioDataInterface
[16-06-22]00:20:48.962 | Info (debug) RESIP:DUM | "Dialog::makeResponse: SIP/2.0 200 OK
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Length: 0

" |
[16-06-22]00:20:48.962 | Info (debug) RESIP:TRANSACTION | “Adding application timer: DumTimeout::Retransmit200 INVITE: 118 UAS_Accepted ADDR=sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c PEER=”“Dialer”“sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a: duration=500 seq=102” |
[16-06-22]00:20:48.962 | Info (debug) RESIP:TRANSACTION | “Adding application timer: DumTimeout::WaitForAck INVITE: 118 UAS_Accepted ADDR=sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c PEER=”“Dialer”“sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a: duration=32000 seq=102” |
[16-06-22]00:20:48.962 | Info (debug) RESIP:DUM | “Looking for dialogSet: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c in map:” |
[16-06-22]00:20:48.962 | Info (debug) RESIP:DUM | “[0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060-d402492c -> 063EB450, 1f7e5343ed08d177ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-22467808 -> 063EB318, 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.-5648cf69 -> 063EB588]” |
[16-06-22]00:20:48.963 | Info (debug) RESIP:DUM | "SEND: SIP/2.0 200 OK
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 241

v=0
o=- 1 2 IN IP4 192.168.1.103
s=CounterPath eyeBeam 1.5
c=IN IP4 192.168.1.103
t=0 0
m=audio 20412 RTP/AVP 0 8 101
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=x-rtp-session-id:37AD6EED9A5E4017B398CD225164F7D4
" |
[16-06-22]00:20:48.963 | Info (debug) RESIP | “SEND: SipResp: 200 tid=0d0b3e8e cseq=INVITE contact=1001@192.168.1.103:48244 / 102 from(tu)” |
[16-06-22]00:20:48.963 | Info (debug) CCM | “SipResp: 200 tid=0d0b3e8e cseq=INVITE contact=1001@192.168.1.103:48244 / 102 from(tu) [1001@ServerDomainName <- Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:48.963 | Info (more) CCM | “[UAS][state:EUASNew_AnswerOrOfferSent][sdp-state:ESDPAnswered] <- [event:onConnected (UAS)] [1001@ServerDomainName <- Rached@0021655534567@27_3@141@ServerIP]” | sua::CSIPCall::PreProcessIncomingEvent
[16-06-22]00:20:48.963 | Info (min) Utilities | “Detected CPU [Intel® Pentium® CPU P6200 @ 2.13GHz]” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:48.963 | Info (more) Utilities | “Detected frequency: 2130” | sua::CProcessorInformation::Detecti386CPU
[16-06-22]00:20:48.964 | Info (more) Audio | “DTX state on stream is 0” | sua::CAudioCodecSelectionManager::StartOutgoingStream
[16-06-22]00:20:48.964 | Info (more) Audio | “CODEC-SWITCH (local): Switching codec to g711u at 8000 Hz using bandwidth 80000 kbps” | sua::CAudioCodecSelectionManager::SetCurrentCodec
[16-06-22]00:20:48.964 | Info (more) Audio | “Outgoing audio stream 000022BB set to state Active” | sua::CAudioCodecSelectionManager::SetOutgoingStreamState
[16-06-22]00:20:48.964 | Info (debug) AbstractPhone | “Adding outgoing audio stream (8891) to media port (104910344)” | AbPhone::CCallMediaPort::AddOutgoingAudioStream
[16-06-22]00:20:48.964 | Info (debug) AbstractPhone | “Adding outgoing stream (8891) to microphone” | AbPhone::CCallMediaHub::AddOutgoingStreamToMicrophone
[16-06-22]00:20:48.964 | Info (debug) AbstractPhone | “OnMediaCommited” | AbPhone::CCall::CCallSessionSink::OnMediaCommited
[16-06-22]00:20:48.964 | Info (debug) AbstractPhone | “OnSIPServerConnected” | AbPhone::CCall::CCallSessionSink::OnSIPServerConnected
[16-06-22]00:20:48.964 | Info (debug) AbstractPhone | “OnMediaSessionRemoteCodec” | AbPhone::CCall::CCallSessionSink::OnMediaSessionLocalCodec
[16-06-22]00:20:48.986 | Info (more) RTP | “RTP SENDING: Starting (first one) to send RTP packages to address: ServerIP:13044” | sua::CRTPDestination::SendRTPEncoded
[16-06-22]00:20:48.987 | Info (more) Audio | “Outgoing audio stream 000022BB set to state Active” | sua::CAudioCodecSelectionManager::SetOutgoingStreamState
[16-06-22]00:20:49.050 | Info (debug) RESIP:TRANSPORT | “Looked up source for destination: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] -> [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] sent-by=ServerIP sent-port=5060” |
[16-06-22]00:20:49.050 | Info (debug) RESIP:TRANSPORT | "Transmitting to [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.1.103:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]SIP/2.0 200 OK
Via: SIP/2.0/UDP ServerIP:5060;branch=z9hG4bK0d0b3e8e;rport=5060
Contact: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c
To: sip:1001@192.168.1.103:48244;rinstance=87df715853d39b2c;tag=d402492c
From: "“Dialer”"sip:Rached%400021655534567%4027_3%40141@ServerIP;tag=as709ad49a
Call-ID: 0332b01c756a7e7b5a37d3680758e59c@ServerIP:5060
CSeq: 102 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1003s stamp 31159
Content-Length: 241

v=0
o=- 1 2 IN IP4 192.168.1.103
s=CounterPath eyeBeam 1.5
c=IN IP4 192.168.1.103
t=0 0
m=audio 20412 RTP/AVP 0 8 101
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=x-rtp-session-id:37AD6EED9A5E4017B398CD225164F7D4
" |
[16-06-22]00:20:49.050 | Info (debug) RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 ServerIP:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:48244 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |
[16-06-22]00:20:49.050 | Info (debug) RESIP:TRANSACTION | “Adding timer: Timer StaleServer tid=0d0b3e8e ms=32000” |
[16-06-22]00:20:49.050 | Info (more) RESIP:DUM | “Got a DumFeatureMessage0325ED98” |
[16-06-22]00:20:49.050 | Info (debug) RESIP:DUM | “contact 192.168.1.103:48244 found for the request SUBSCRIBE sip:1001@ServerDomainName SIP/2.0
Via: SIP/2.0/ ;branch=z9hG4bK-d87543-9c19b41a821a7c2b-1–d87543-;rport
Max-Forwards: 70
Contact: sip:1001@192.168.1.103:48244
To: ““Agent1"“sip:1001@ServerDomainName
From: ““Agent1"“sip:1001@ServerDomainName;tag=5648cf69
Call-ID: 9c0a6c5ee81e6670ZjhmMTZkZGRlMjBkNmU4Y2VhMjYyOThjNWQ2OGFiOGU.
CSeq: 2 SUBSCRIBE
Expires: 300
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: eyeBeam release 1003s stamp 31159
Authorization: Digest username=”“1001"”,realm=”“asterisk””,nonce=”“7d7a2268"”,uri=”“sip:1001@ServerDomainName””,response=”“ecd8b1db1574a687783cd54152cae973"”,algorithm=MD5
Event: message-summary
Content-Length: 0

As I remarked there is 3-4 seconds softphone try to make call answered (as I said “Auto-Answer” feature activated), but didn’t response from server . Isn’t ?

wilwil · June 22, 2016, 1:57am

For Networking state in remote end I’ll get it as soon as possible.
Also for changing internet provider I’ll do something to test it.

Topic		Replies	Views
Ring delays for the next available agent Asterisk Support	5	378	January 27, 2016
Queue Delay Asterisk Support	0	119	September 29, 2006
Big delay in bridging queue calls Asterisk Support	5	937	June 3, 2021
Queue routing delay Asterisk Support	4	218	February 27, 2012
app_queue - ringing extension blocks other calls Asterisk Support	5	466	November 6, 2006

Strange Queue delay ringing its agents

Related topics