Sip server clears nomal calls as idle

[deadmeat]

Hi friends, maybe you can help. We have an issue, when I enable stuck calls clearence in SIP server call cleanup section. It releases normal calls treating them as idle:

[code]
@15:01:07.1113 Call 008202daccd2c647 idle timeout expired -- initiating call cleanup
15:01:07.111: SIPTS: SipTServer::CheckCall call-id 22843592 - lets call deleting be handled regular way
15:01:07.121: SD: none
15:01:07.121: GetRegistration::Unable to resolve number for DN:994555902585
15:01:07.122 SIPCONN(994555902585): ClrMediaPeer
15:01:07.122 SIPCONN(9900): ClrMediaPeer
15:01:07.122 SIPCONN(9900): CheckUpdateTransferStatus: no original dialog
15:01:07.122: GetRegistration::Unable to resolve number for DN:994555902585
15:01:07.122 SIPCONN(994555902585): set monitor ecd6220, 0
15:01:07.122 SIPCONN(994555902585): state e:1,p:3,s:0,c:11,rc:0,m:0
15:01:07.122: SipDialog: ClearCall(phone=0,state=7)
15:01:07.122: SipDialog::Terminate(state=7,reason=0)
15:01:07.122: SIPDLG[16991899]: register TRN[66342212]
15:01:07.122: Sending  [0,UDP] 451 bytes to 10.76.0.161:5060 >>>>>
BYE sip:10.76.0.161:5060 SIP/2.0
[/code]

Any ideas ? What could be the reason of such behaivoir ? I was suspecting incorrect configuration of session timer, but as I see in SIP logs it refreshes every minute:
[code]
15:01:05.552: HA:MESSAGE:TYPE[sipStackSync]: SYNCED
15:01:05.552: SipDialog: event CONNECTED_SEND_ACK, t=66342181, s=7, r=7, m=a089158 port=5060
15:01:05.552: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
15:01:05.552 SIPCONN(9900): HandleSipDialogEvent(CONNECTED_SEND_ACK) - filtered
15:01:05.552 SIPCONN(9900): TRCLR(66342181)
15:01:05.552: SIPTR(116922359): complete
15:01:05.552: SIPTR(116922358): Step 0 - SipTransactionRefresh(116922359) complete
15:01:05.552: SIPTR(116922358): complete
15:01:05.552: SIPCM: transaction SipScenario(116922358) complete
15:01:05.552: PI: 00 S[CI]D[994555902585]C[*D[994555902585]]P[9900]
15:01:05.552: PI: 00 S[CA]D[9900]C[*D[9900]]P[994555902585]
15:01:05.552: CALLSTATE(a:2,d:0,i:0,e:1,r:0,o:0)
15:01:05.552: -----------------------------------------------------------
15:01:05.552: C[22843592]:CF[D[[0]]:SC[116922358]
15:01:05.552: P[22709348][994555902585[67191443]]:LID[0]:CS[3]D2[9900[67191447]]:
15:01:05.552 SIPCONN(994555902585):  endPoint :CON[16992254]STATE[3]:PEER[16992255][994555902585[67191443]]:DLG[16991899 STATE[7]]:D2[[0]:TD[0[IM[no]]]:LCRC
15:01:05.552: P[22709350][9900[67191447]]:LID[0]:CS[3]D2[994555902585[67191443]]:
15:01:05.552 SIPCONN(9900):  endPoint :CON[16992255]STATE[3]:PEER[16992254][9900[67191447]]:DLG[16991900 STATE[7]]:D2[994555902585[67191443]:TD[0[IM[no]]]:LCRC
15:01:05.552: HA: BEGIN SYNC: CALL[22843592] SYNCTYPE[2]: SECOND CALL[0] SYNCTYPE[-1]
15:01:05.553: HA: END SYNC: CALL[22843592] SYNCTYPE[2]: SECOND CALL[0] SYNCTYPE[-1]
@15:01:05.5533 [BSYNC] Trace: Send to backup (SIP_b) [50]:
message EventUserEvent
attr_#1005 0
attr_#1004 553
attr_#1003 1563447665
attr_#1002 137578007
attr_#1001 1
attr_#1000 131072
attr_#15999 1
attr_#16704 1
attr_#16000 1
attr_#16102 [446] 32 3a 31 7c..
attr_#16101 [408] 32 3a 31 7c..
attr_#16100 [107] 31 3a 31 7c..
AttributeUserEvent [16001]
@15:01:05.5533 [BSYNC] Trace: Sent
15:01:05.553: HA:MESSAGE:TYPE[callSync:]: SYNCED
15:01:05.553: call1 22843592 idle
15:01:05.553: $-NET:SIP::0:0
[/code]

Any ideas ? Will apreceate any help.

[Kubig]

The timer takes into account the time from last SIP message belongs to SIP session, it has nothing to do with T-Lib messages at all. So, check your SIP signalization what happened there

[deadmeat]

Thanks for reply. I do aware about SIP events and Tlib events. I've posted part of the log not the full log. And of course there are SIP INVITES e.t.c. in them. My question is if enable stuck call handling (cleanup-idle-tout and 2 other options) is it normal if this option dropes the ACTIVE calls ? Below is the part of the log with SIP event for session refreshing and Tlib event triggered by it. Why I am posting it is that to make sure that SIP server is aware that call is active not stuck, but it clears it anyway after the tim specified in cleanup-idle-tout no matter what. I think this behavour is incorrect and abnormal. Correct me if I'm wrong.

[code]
14:53:04.672: SipDialog: event SE_REFRESH, t=0, s=7, r=5, m=a089158 port=5060
14:53:04.672: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
14:53:04.672 SIPCONN(9900): HandleSipDialogEvent(SE_REFRESH)
14:53:04.672: SIPTR(116912119): Begin step 0 - SipTransactionRefresh(116912120)
14:53:04.672 SIPCONN(9900): initiate refresh
14:53:04.672: SIPDLG[16991900]: register TRN[66336437]
14:53:04.672: SIPDLG[16991900]: TRN[66336437] flags set to 0x6
14:53:04.672: Sending  [0,UDP] 1264 bytes to 10.240.2.220:5060 >>>>>
INVITE sip:9900@10.240.2.220:5060 SIP/2.0
From: "994555902585" <sip:994555902585@10.76.0.161;transport=udp;user=phone>;tag=0009736A-2862-1CB3-8D58-0539DC0AAA77-22866580
To: <sip:6931@10.220.56.10:5060>;tag=1369625616
Call-ID: 00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10
CSeq: 6 INVITE
Content-Length: 593
Content-Type: application/sdp
Via: SIP/2.0/UDP 10.220.56.10:5060;branch=z9hG4bK00097388-2862-1CB3-8D58-0539DC0AAA77-51073786
Contact: <sip:994555902585@10.220.56.10:5060>
Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, MESSAGE, NOTIFY, OPTIONS
Max-Forwards: 69
Session-Expires: 90;refresher=uac
Min-SE: 90
Supported: 100rel,timer

v=0
o=HuaweiSoftx3000 1734373742 1 IN IP4 10.76.3.18
s=SipCall
c=IN IP4 10.76.3.18
t=0 0
m=audio 2320 RTP/AVP 101 108 102 8 116 107
a=ptime:20
a=curr:qos local none
a=curr:qos remote none
a=des:qos mandatory local sendrecv
a=des:qos optional remote sendrecv
a=3gOoBTC
a=rtpmap:101 AMR-WB/16000
a=fmtp:101 mode-set=0,1,2
a=rtpmap:108 AMR/8000
a=fmtp:108 mode-change-neighbor=1;mode-change-period=2
a=rtpmap:102 AMR/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:116 telephone-event/8000
a=rtpmap:107 AMR/8000
a=fmtp:107 mode-set=0,1,2,3,4,5;mode-change-neighbor=1;mode-change-period=2

14:53:04.672: SipDialog: event CONNECTED_SEND_REINVITE, t=66336437, s=7, r=8, m=a089158 port=5060
14:53:04.672: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
14:53:04.672 SIPCONN(9900): HandleSipDialogEvent(CONNECTED_SEND_REINVITE) - filtered
14:53:04.686: $+NET:SIP::0:0
14:53:04.686: SIPTR: Received [0,UDP] 440 bytes from 10.240.2.220:5060 <<<<<
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.220.56.10:5060;branch=z9hG4bK00097388-2862-1CB3-8D58-0539DC0AAA77-51073786
From: "994555902585" <sip:994555902585@10.76.0.161;transport=udp;user=phone>;tag=0009736A-2862-1CB3-8D58-0539DC0AAA77-22866580
To: <sip:6931@10.220.56.10:5060>;tag=1369625616
Call-ID: 00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10
CSeq: 6 INVITE
User-Agent: Yealink SIP-T23G 44.84.0.15
Content-Length: 0


14:53:04.686: SipDialog: event CONNECTED_RESPROV, t=66336437, s=7, r=5, m=a089158 port=5060
14:53:04.686: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
14:53:04.686 SIPCONN(9900): HandleSipDialogEvent(CONNECTED_RESPROV)
14:53:04.686 SIPCONN(9900): handle refresh event
14:53:04.686: $-NET:SIP::0:0

14:53:04.709: $+NET:SIP::0:0
14:53:04.709: SIPTR: Received [0,UDP] 958 bytes from 10.240.2.220:5060 <<<<<
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.220.56.10:5060;branch=z9hG4bK00097388-2862-1CB3-8D58-0539DC0AAA77-51073786
From: "994555902585" <sip:994555902585@10.76.0.161;transport=udp;user=phone>;tag=0009736A-2862-1CB3-8D58-0539DC0AAA77-22866580
To: <sip:6931@10.220.56.10:5060>;tag=1369625616
Call-ID: 00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10
CSeq: 6 INVITE
Contact: <sip:9900@10.240.2.220:5060>
Content-Type: application/sdp
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Session-expires: 90;refresher=uac
User-Agent: Yealink SIP-T23G 44.84.0.15
Supported: timer
Allow-Events: talk,hold,conference,refer,check-sync
Require: timer
Content-Length: 211

v=0
o=- 20002 20006 IN IP4 10.240.2.220
s=SDP data
c=IN IP4 10.240.2.220
t=0 0
m=audio 12576 RTP/AVP 8 116
a=rtpmap:8 PCMA/8000
a=ptime:20
a=rtpmap:116 telephone-event/8000
a=fmtp:116 0-15
a=sendrecv

14:53:04.709: SipDialog: event CONNECTED_RESOK, t=66336437, s=7, r=5, m=a089158 port=5060
14:53:04.709: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
14:53:04.709 SIPCONN(9900): HandleSipDialogEvent(CONNECTED_RESOK)
14:53:04.709 SIPCONN(9900): handle refresh event
14:53:04.709: Sending  [0,UDP] 434 bytes to 10.240.2.220:5060 >>>>>
ACK sip:9900@10.240.2.220:5060 SIP/2.0
From: "994555902585" <sip:994555902585@10.76.0.161;transport=udp;user=phone>;tag=0009736A-2862-1CB3-8D58-0539DC0AAA77-22866580
To: <sip:6931@10.220.56.10:5060>;tag=1369625616
Call-ID: 00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10
CSeq: 6 ACK
Content-Length: 0
Via: SIP/2.0/UDP 10.220.56.10:5060;branch=z9hG4bK00097388-2862-1CB3-8D58-0539DC0AAA77-51073787
Max-Forwards: 69


@14:53:04.7093 [BSYNC] Trace: Send to backup (SIP_b) [50]:
message EventUserEvent
attr_#1005 0
attr_#1004 709
attr_#1003 1563447184
attr_#1002 137565791
attr_#1001 1
attr_#1000 131072
attr_#15999 1
attr_#16704 1
attr_#16000 1
attr_#16500 [554] 31 3d 33 0d..
AttributeUserEvent [16099]
@14:53:04.7093 [BSYNC] Trace: Sent
14:53:04.709: HA:MESSAGE:TYPE[sipStackSync]: SYNCED
14:53:04.709: SipDialog: event CONNECTED_SEND_ACK, t=66336437, s=7, r=7, m=a089158 port=5060
14:53:04.709: CID:CUUID>00097338-2862-1CB3-8D58-0539DC0AAA77-14202152@10.220.56.10:0097VS18C8EB73AO0KSTO2LAES05P370:
14:53:04.709 SIPCONN(9900): HandleSipDialogEvent(CONNECTED_SEND_ACK) - filtered
14:53:04.709 SIPCONN(9900): TRCLR(66336437)
14:53:04.709: SIPTR(116912120): complete
14:53:04.709: SIPTR(116912119): Step 0 - SipTransactionRefresh(116912120) complete
14:53:04.709: SIPTR(116912119): complete
14:53:04.709: SIPCM: transaction SipScenario(116912119) complete
14:53:04.709: PI: 00 S[CI]D[994555902585]C[*D[994555902585]]P[9900]
14:53:04.709: PI: 00 S[CA]D[9900]C[*D[9900]]P[994555902585]
14:53:04.709: CALLSTATE(a:2,d:0,i:0,e:1,r:0,o:0)
14:53:04.709: -----------------------------------------------------------
14:53:04.709: C[22843592]:CF[D[[0]]:SC[116912119]
14:53:04.709: P[22709348][994555902585[67191443]]:LID[0]:CS[3]D2[9900[67191447]]:
14:53:04.709 SIPCONN(994555902585):  endPoint :CON[16992254]STATE[3]:PEER[16992255][994555902585[67191443]]:DLG[16991899 STATE[7]]:D2[[0]:TD[0[IM[no]]]:LCRC
14:53:04.709: P[22709350][9900[67191447]]:LID[0]:CS[3]D2[994555902585[67191443]]:
14:53:04.709 SIPCONN(9900):  endPoint :CON[16992255]STATE[3]:PEER[16992254][9900[67191447]]:DLG[16991900 STATE[7]]:D2[994555902585[67191443]:TD[0[IM[no]]]:LCRC
14:53:04.709: HA: BEGIN SYNC: CALL[22843592] SYNCTYPE[2]: SECOND CALL[0] SYNCTYPE[-1]
14:53:04.709: HA: END SYNC: CALL[22843592] SYNCTYPE[2]: SECOND CALL[0] SYNCTYPE[-1]
[/code]