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 [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/
