Andy,
I made some changes on the main sipxtapi branch to solve this -- and I believe it was merged to the sipxtapi-media-update branch, but I'm not positive. Would you mind updating? Also -- if you don't need the changes that Alexander is making, I recommend using the sipXtapi branch -- it is likely more stable.
-
Bob
On 8/10/06, Andy <[EMAIL PROTECTED]> wrote:
As posted earlier this week, with the latest updates to media-update I'm
getting a long timeout and blocking on sipxCallConnect now. One of the
timeouts is in getCalledAddresses - but there seems to be another one
when the callstate goes from CONNECTION_IDLE to CONNECTION_ESTABLISHED.
It's right at 24 seconds. The call does connect after the timeout.
I've done some minimal digging, but haven't turned up too much yet. In
all instances I'm specifically binding to a single IP. Below is the
area in the log where it's happening. Look at the timestamps.
Andy M.
[EMAIL PROTECTED]
"2006-08-09T23:34:47.813000Z":252:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallConnect\n"
"2006-08-09T23:34: 47.813000Z":254:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxCallGetID\n"
"2006-08-09T23:34:47.813000Z":253:SIPXTAPI:INFO:andy::00000000:sipXtapi:"sipxCallConnect
hCall=1 szAddress=[EMAIL PROTECTED] contactId=0
bEnableLocationHeader=0 bandWidth=5"
"2006-08-09T23:34:47.813000Z":255:SIPXTAPI:INFO:andy:SipXEventDispatcher-19:00000770:sipXtapi:"sipxCallGetID
hCall=1"
"2006-08-09T23:34:47.828000Z":256:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxCallGetCommonData\n"
"2006-08-09T23:34:47.828000Z ":257:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxCallGetCommonData->sipxCallLookup\n"
"2006-08-09T23:34:47.828000Z":258:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallGetCommonData\n"
"2006-08-09T23:34:47.828000Z":259:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallGetCommonData->sipxCallLookup\n"
"2006-08-09T23:34: 47.828000Z":260:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxCallGetCommonData->sipxCallLookup\n"
"2006-08-09T23:34:47.828000Z":261:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallGetCommonData->sipxCallLookup\n"
"2006-08-09T23:34:47.828000Z":262:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxCallGetCommonData->sipxCallReleaseLock\n"
"2006-08-09T23:34:47.828000Z":263:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallGetCommonData->sipxCallReleaseLock\n"
"2006-08-09T23:34:47.828000Z":264:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxCallGetCommonData->sipxCallReleaseLock\n"
"2006-08-09T23:34:47.828000Z":265:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallGetCommonData->sipxCallReleaseLock\n"
"2006-08-09T23:34:47.828000Z":266:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxCallGetCommonData\n"
"2006-08-09T23:34:47.828000Z":267:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallGetCommonData\n"
"2006-08-09T23:34:47.828000Z":268:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxCallGetID\n"
"2006-08-09T23:34: 47.828000Z":269:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxLineGetURI\n"
"2006-08-09T23:34:47.828000Z":270:SIPXTAPI:INFO:andy:SipXEventDispatcher-19:00000770:sipXtapi:"sipxLineGetURI
hLine=1"
"2006-08-09T23:34:47.828000Z":272:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallConnect->sipxCallLookup\n"
"2006-08-09T23:34:47.828000Z":273:CP:DEBUG:andy:Call-23:0000016C:sipXtapi:"CpCall::handleMessage
message type: 5 subtype 42\n"
"2006-08-09T23:34:47.828000Z":271:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxLineGetURI->sipxLineLookup\n"
"2006-08-09T23:34:47.828000Z":274:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallConnect->sipxCallLookup\n"
"2006-08-09T23:34:47.828000Z":275:CP:DEBUG:andy:Call-23:0000016C:sipXtapi:"CpCall::handleMessage
message type: 5 subtype 75\n"
"2006-08-09T23:34:47.828000Z":276:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallConnect->sipxCallReleaseLock\n"
"2006-08-09T23:34: 47.828000Z":277:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallConnect->sipxCallReleaseLock\n"
"2006-08-09T23:34:47.828000Z":278:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxLineGetURI->sipxLineLookup\n"
"2006-08-09T23:34:47.828000Z":279:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"ENTER
FUNC (tid=1904) sipxLineGetURI->sipxLineReleaseLock\n"
"2006-08-09T23:34:47.828000Z":280:CP:INFO:andy:CallManager-17:00000B4C:sipXtapi:"Running
postMessage with CallId: call_19560001_7bace00b1d3f7e49\n"
"2006-08-09T23:34:47.828000Z":281:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxLineGetURI->sipxLineReleaseLock\n"
"2006-08-09T23:34:47.828000Z":282:CP:DEBUG:andy:Call-23:0000016C:sipXtapi:"CpCall::handleMessage
message type: 5 subtype 3\n"
"2006-08-09T23:34:47.828000Z":283:SIPXTAPI:DEBUG:andy:SipXEventDispatcher-19:00000770:sipXtapi:"EXIT
FUNC (tid=1904) sipxLineGetURI\n"
"2006-08-09T23:34:47.828000Z":284:CP:INFO:andy:CallManager-17:00000B4C:sipXtapi:"Running
setLocalConnectionState with CallId: call_19560001_7bace00b1d3f7e49\n"
"2006-08-09T23:34:47.828000Z":285:CP:INFO:andy:CallManager-17:00000B4C:sipXtapi:"Running
stopMetaEvent with CallId: call_19560001_7bace00b1d3f7e49\n"
"2006-08-09T23:34:47.828000Z":286:CP:INFO:andy:CallManager-17:00000B4C:sipXtapi:"doConnect
is done CallId: call_19560001_7bace00b1d3f7e49\n"
"2006-08-09T23:34:47.828000Z":287:CP:DEBUG:andy::00000000:sipXtapi:"CallManager::getCalledAddresses
waiting\n"
"2006-08-09T23:34:47.984000Z":288:MP:DEBUG:andy:NetInTask:00000D80:sipXtapi:"
*** NetInTask: Adding new RTP/RTCP sockets (RTP:045E6410,6344,
RTCP:045E67C8,6360)\n"
"2006-08-09T23:34: 47.984000Z":289:MP:DEBUG:andy:NetInTask:00000D80:sipXtapi:"
*** NetInTask: Add socket Fds: RTP=045E6410, RTCP=045E67C8, Q=045E3F80\n"
"2006-08-09T23:34:47.984000Z":290:NET:INFO:andy:Call-23:0000016C:sipXtapi:"Stun
enabled for 192.168.15.100:9000 with server proxy01.icall.com:3478
options=0, keepAlive=24"
"2006-08-09T23:34:47.984000Z ":291:NET:DEBUG:andy:Call-23:0000016C:sipXtapi:"Outbound
STUN/TURN message(Crude Parse):\nMsg t=0x0001/MSG_STUN_BIND_REQUEST,
l=0, id=8BB80EE8/06F69F263D645A210231E010\n\n"
"2006-08-09T23:34:48.000000Z ":292:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Inbound
STUN message (Crude Parse):\nMsg t=0x0101/MSG_STUN_BIND_RESPONSE, l=36,
id=8BB80EE8/06F69F263D645A210231E010\nattr
t=0x0001/ATTR_STUN_MAPPED_ADDRESS, l=8\n v=00012328436AFFFFFF\nattr
t=0x0005/ATTR_STUN_CHANGED_ADDRESS, l=8\n v=00010DFFF452A5704\nattr
t=0x0004/ATTR_STUN_SOURCE_ADDRESS, l=8\n v=00010DFFF452A5705\n\n"
"2006-08-09T23:34:48.000000Z":293:NET:INFO:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Stun
success for 192.168.15.100:9000, mapped address: XXX.XXX.XXX.XXX:9000"
"2006-08-09T23:34:48.500000Z":294:NET:INFO:andy:Call-23:0000016C:sipXtapi:"Stun
enabled for 192.168.15.100:9001 with server proxy01.icall.com:3478
options=0, keepAlive=24"
"2006-08-09T23:34:48.500000Z ":295:NET:DEBUG:andy:Call-23:0000016C:sipXtapi:"Outbound
STUN/TURN message(Crude Parse):\nMsg t=0x0001/MSG_STUN_BIND_REQUEST,
l=0, id=8BB80EE8/E52DAC5C31B02EF6470A8ADE\n\n"
"2006-08-09T23:34:48.531000Z ":296:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Inbound
STUN message (Crude Parse):\nMsg t=0x0101/MSG_STUN_BIND_RESPONSE, l=36,
id=8BB80EE8/E52DAC5C31B02EF6470A8ADE\nattr
t=0x0001/ATTR_STUN_MAPPED_ADDRESS, l=8\n v=00012329436AFFFFFF\nattr
t=0x0005/ATTR_STUN_CHANGED_ADDRESS, l=8\n v=00010DFFF452A5704\nattr
t=0x0004/ATTR_STUN_SOURCE_ADDRESS, l=8\n v=00010DFFF452A5705\n\n"
"2006-08-09T23:34:48.531000Z":297:NET:INFO:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Stun
success for 192.168.15.100:9001, mapped address: XXX.XXX.XXX.XXX:9001"
"2006-08-09T23:34:49.031000Z":298:MP:DEBUG:andy:MpMedia:00000958:sipXtapi:"MprDecode::handleSelectCodecs
pCodecs[0]->getCodecType() = 113, pCodecs[0]->getCodecPayloadFormat() = 113"
"2006-08-09T23:34:49.031000Z":299:MP:DEBUG:andy:MpMedia:00000958:sipXtapi:"MprDecode::handleSelectCodecs
pCodecs[1]->getCodecType() = 128, pCodecs[1]->getCodecPayloadFormat() = 96"
"2006-08-09T23:34:49.031000Z":300:MP:INFO:andy:MpMedia:00000958:sipXtapi:"MpdPtAVT(0x45EDCF0)::MpdPtAVT(96)\n"
"2006-08-09T23:34:49.031000Z":301:MP:DEBUG:andy:MpMedia:00000958:sipXtapi:"MpdAVT:
registered with JB (pt=96), res=0\n"
"2006-08-09T23:34:50.828000Z":302:CP:ERR:andy::00000000:sipXtapi:"CallManager::getCalledAddresses
TIMED OUT\n"
"2006-08-09T23:34:50.828000Z":303:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"sipxCallConnect
connected hCall=1 callId=call_19560001_7bace00b1d3f7e49, numAddr = 0,
addr = "
"2006-08-09T23:34:52.016000Z":304:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallConnect->sipxCallLookup\n"
"2006-08-09T23:34:52.016000Z":305:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallConnect->sipxCallLookup\n"
"2006-08-09T23:34:52.016000Z":306:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"ENTER
FUNC (tid=3916) sipxCallConnect->sipxCallReleaseLock\n"
"2006-08-09T23:34:52.016000Z":307:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallConnect->sipxCallReleaseLock\n"
"2006-08-09T23:34:52.016000Z":308:SIPXTAPI:DEBUG:andy::00000000:sipXtapi:"EXIT
FUNC (tid=3916) sipxCallConnect\n"
"2006-08-09T23:35:07.688000Z":309:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Outbound
STUN/TURN message(Crude Parse):\nMsg t=0x0001/MSG_STUN_BIND_REQUEST,
l=0, id=8BB80EE8/BDD297EAFBDC73AEEA9CC349\n\n"
"2006-08-09T23:35:07.703000Z":310:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Inbound
STUN message (Crude Parse):\nMsg t=0x0101/MSG_STUN_BIND_RESPONSE, l=36,
id=8BB80EE8/BDD297EAFBDC73AEEA9CC349\nattr
t=0x0001/ATTR_STUN_MAPPED_ADDRESS, l=8\n v=0001102E436AFFFFFF\nattr
t=0x0005/ATTR_STUN_CHANGED_ADDRESS, l=8\n v=00010DFFF452A5704\nattr
t=0x0004/ATTR_STUN_SOURCE_ADDRESS, l=8\n v=00010DFFF452A5705\n\n"
"2006-08-09T23:35:07.703000Z":311:NET:INFO:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Stun
success for 192.168.15.100:4142, mapped address: XXX.XXX.XXX.XXX:4142"
"2006-08-09T23:35:12.000000Z":312:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Outbound
STUN/TURN message(Crude Parse):\nMsg t=0x0001/MSG_STUN_BIND_REQUEST,
l=0, id=8BB80EE8/89026ED029571144F3C1B4F7\n\n"
"2006-08-09T23:35:12.016000Z":313:MP:DEBUG:andy:NetInTask:00000D80:sipXtapi:"
*** NetInTask: Remove socket Fds: RTP=045E6410, RTCP=045E67C8, Q=045E3F80\n"
"2006-08-09T23:35:12.016000Z":314:NET:DEBUG:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Inbound
STUN message (Crude Parse):\nMsg t=0x0101/MSG_STUN_BIND_RESPONSE, l=36,
id=8BB80EE8/89026ED029571144F3C1B4F7\nattr
t=0x0001/ATTR_STUN_MAPPED_ADDRESS, l=8\n v=00012328436AFFFFFF\nattr
t=0x0005/ATTR_STUN_CHANGED_ADDRESS, l=8\n v=00010DFFF452A5704\nattr
t=0x0004/ATTR_STUN_SOURCE_ADDRESS, l=8\n v=00010DFFF452A5705\n\n"
"2006-08-09T23:35:12.016000Z":315:MP:DEBUG:andy:NetInTask:00000D80:sipXtapi:"
*** NetInTask: Adding new RTP/RTCP sockets (RTP:045E6410,6344,
RTCP:045E67C8,6360)\n"
"2006-08-09T23:35:12.016000Z ":316:MP:DEBUG:andy:NetInTask:00000D80:sipXtapi:"
*** NetInTask: Add socket Fds: RTP=045E6410, RTCP=045E67C8, Q=045E3F80\n"
"2006-08-09T23:35:12.016000Z":317:NET:INFO:andy:OsNatAgentTask-5:00000C0C:sipXtapi:"Stun
success for 192.168.15.100:9000, mapped address: XXX.XXX.XXX.XXX:9000"
"2006-08-09T23:35:12.016000Z":318:CP:DEBUG:andy:Call-23:0000016C:sipXtapi:"Call
Call-23 call_19560001_7bace00b1d3f7e49 state isLocal 1\nchange\nfrom
CONNECTION_IDLE to\n CONNECTION_ESTABLISHED\ncause=0\npost change to
upper layer 1"
_______________________________________________
sipxtapi-dev mailing list
[email protected]
List Archive: http://list.sipfoundry.org/archive/sipxtapi-dev/
_______________________________________________ sipxtapi-dev mailing list [email protected] List Archive: http://list.sipfoundry.org/archive/sipxtapi-dev/
