What I see in the log where they first differ is just after FS
sends the CANCEL to the original ringing phone. FS logs a cause:
PICKED_OFF when it didn't work. Do you know what PICKED_OFF
means?
In the good case, FS logs:
tport_pend(0x88348e8): pending 0x8942cc0 for
udp/192.168.72.141:5060 (already 1)
2010-03-04 12:13:04.772196 [DEBUG]
switch_core_state_machine.c:585 (sofia/internal/sip:5381@192.168.72.58:5060)
State REPORTING
2010-03-04 12:13:04.772196 [DEBUG]
switch_core_state_machine.c:53 sofia/internal/sip:5381@192.168.72.58:5060
Standard REPORTING, cause: ORIGINATOR_CANCEL
2010-03-04 12:13:04.772196
[DEBUG] switch_core_state_machine.c:585
(sofia/internal/sip:5381@192.168.72.58:5060) State REPORTING going to
sleep
2010-03-04 12:13:04.772196 [DEBUG] switch_core_state_machine.c:327
(sofia/internal/sip:5381@192.168.72.58:5060) State Change CS_REPORTING ->
CS_DESTROY
2010-03-04 12:13:04.772196 [DEBUG] switch_core_session.c:1019 Send
signal sofia/internal/sip:5381@192.168.72.58:5060 [BREAK]
2010-03-04
12:13:04.772196 [DEBUG] switch_core_session.c:1161 Session 177
(sofia/internal/sip:5381@192.168.72.58:5060) Locked, Waiting on external
entities
In the bad case, FS logs:
tport_pend(0x88348e8): pending 0xb6dd6468 for
udp/192.168.72.141:5060 (already 1)
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_state_machine.c:333 (sofia/internal/sip:5381@192.168.72.58:5060)
State Change CS_HANGUP -> CS_REPORTING
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_session.c:1019 Send signal
sofia/internal/sip:5381@192.168.72.58:5060 [BREAK]
2010-03-04 12:33:45.001563
[DEBUG] switch_core_state_machine.c:314
(sofia/internal/sip:5381@192.168.72.58:5060) Running State Change
CS_REPORTING
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_state_machine.c:585 (sofia/internal/sip:5381@192.168.72.58:5060)
State REPORTING
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_state_machine.c:53 sofia/internal/sip:5381@192.168.72.58:5060
Standard REPORTING, cause: PICKED_OFF
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_state_machine.c:585 (sofia/internal/sip:5381@192.168.72.58:5060)
State REPORTING going to sleep
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_state_machine.c:327 (sofia/internal/sip:5381@192.168.72.58:5060)
State Change CS_REPORTING -> CS_DESTROY
2010-03-04 12:33:45.001563 [DEBUG]
switch_core_session.c:1019 Send signal
sofia/internal/sip:5381@192.168.72.58:5060 [BREAK]
2010-03-04 12:33:45.001563
[DEBUG] switch_core_session.c:1161 Session 199
(sofia/internal/sip:5381@192.168.72.58:5060) Locked, Waiting on external
entities
2010-03-04 12:33:45.001563 [DEBUG] switch_core_session.c:1019 Send
signal sofia/internal/1059@192.168.72.141:5060 [BREAK]
2010-03-04 12:33:45.001563
[NOTICE] switch_ivr_bridge.c:740 Hangup sofia/internal/5402@192.168.72.141:5060 [CS_SOFT_EXECUTE]
[ORIGINATOR_CANCEL]
Best Regards,
Jerry
On Thu, Mar 4, 2010 at 2:14 PM, Jerry Richards
<jerry.richards@teotech.com>
wrote:
By the way, it appears that the "**<extension>"
ringing call pickup feature
is intermittent. Sometimes it works,
sometimes not. I posted two traces of
the following
scenario:
1) 1059 calls 5381
2) 5381 rings
3) 5402 dials
"**5381"
In the bad case (http://pastebin.freeswitch.org/12325), all calls
disconnect
following above scenario. In the good case
(http://pastebin.freeswitch.org/12326), 5402 connects to
1059.
Best Regards,
Jerry
I'd suggest turning off the sofia debug stuff cuz that's just line
noise unless you know all that stuff. You need to compare the two traces and
look for differences. I'd start by looking at only the fs console output of
each call and see if there's anything different between the two. See if
there's a point where they diverge and work your way back from there. Look at
the corresponding SIP dialogs and see if there are any clues as well. You may
also want to capture the SIP traffic with tcpdump and analyze it in Wireshark
which is easier on the eyes than having it buried in with the sofia and
console logs.
FWIW, I just updated to latest and I can't make this
feature *NOT* work. I'm on 32-bit CentOS using Polycom 550 and Snom 320
phones.
-MC