SEMS 1.5 - 1.7: CANCEL race conditions leads to hanging calls.

[sems-server]

SEMS 1.5 - 1.7: CANCEL race conditions leads to hanging calls.

[juha-h]

Earn330 writes:

But I think it should answer the wrong OK with an 481 Call Leg does not exist or something like that, because on the one hand the b-side who picked up the call, thinks there is no audio, because the call seems to be established. On the other hand the call stucks in SEMS even if the b-side terminates the call with a BYE. To show you an example, I attached a broken call flow where one of our customers had network issues. SEMS is listening on 192.168.253.20:5080 and 127.0.0.1:5080 192.168.253.20:5060 and 127.0.0.1:5060 is our Kamailio Proxy. 192.168.253.60 is an Oracle ACME Packet. Our customer is 82.97.138.31.

Lots of moving parts and some of the addresses are not in above explanation, Try to reproduce the issue in a simpler setup, perhaps using sipp.

…

-- Juha

[Earn330]

I was able to reproduce the problerm in our lab in much smaller enviroment. Also I was able to make debug logs.

To make the scenario clear:
Callflow is
PSTN ---> ACME Packet ---> SEMS ---> Customer

As the error does not occur befor the call is going through sems, we leave the part out. So left is

SEMS outbound -> Customer inbound

SEMS outbound is 127.0.0.1:5080 and customer inbound is 127.0.0.1:5060

Now the following error happens:

SEMS Customer
INVITE --------------->
100 trying <-----------

Now customer has network errors so after some time A-Side is cancellig

CANCEL -------------->

Suddenly network operates and buffered Message are going through

200 OK (INVITE) <----- (this is wrong. Error message in SEMS occours)
200 OK (CANCEL) <--- (too bad, but SEMS is awaiting ACK from other side that doesn't exist anymore)

The A-Side times out. The B-Side stucks even after sending a BYE and a reply of 481 Call Leg does not exist.
So here you have my logfile, pcap and sipp scenario. I hope you'll find something

BR, Bjoern
sems_debug.log
sipp_uas.zip
sems_cancel_error.pcap.zip

[Earn330]

Hi Juha,

please apologize my impatience, but have you had the time to take a look at my last post?

BR, Bjoern

[juha-h]

Earn330 writes:

please apologize my impatience, but have you had the time to take a look at my last post?

Sorry, I have been traveling and I'm still on the road. According to RFC3261, what it is that SEMS should be doing?

…

-- Juha

[Earn330]

Hi Juha

As far as my investigation goes, according to RFC everything is fine in SEMS. The problem is, that the call is not deleted from active calls after the timeout. Doing a sems-list-active-calls is then still showing the active B-leg. This one is only deleted by restarting SEMS.
The A-leg is deleted normally.
Although I see a couple of timers running into timeout in debug log, the callleg is never deleted until restart.

BR, Bjoern

[juha-h]

Earn330 writes:

So here you have my logfile, pcap and sipp scenario. I hope you'll find something BR, Bjoern [sems_debug.log](https://github.com/sems-server/sems/files/1454614/sems_debug.log) [sipp_uas.zip](https://github.com/sems-server/sems/files/1454616/sipp_uas.zip) [sems_cancel_error.pcap.zip](https://github.com/sems-server/sems/files/1454617/sems_cancel_error.pcap.zip)

sipp_uas.zip seems to only contain empty sipp_uas directory. You use sems sbc application. Have you tried if the issue exists without sbc, e.g., using a simple b2b application?

…

-- Juha

[juha-h]

Earn330 writes:

Callflow is PSTN ---> ACME Packet ---> SEMS ---> Customer

Does SEMS reply 200 OK INVITE and then send a new INVITE to Customer, i.e., is there two separate call legs or is the call relay-only?

…

-- Juha

[Earn330]

Hi,

what do you mean with simple b2b? Is it documented somewhere? Are there examples for configuration.
That call itself is relay only through SEMS. We need this to rewrite some ids to prevent our PSTN switch to drop the call in redirection cases.
I will have a look at the empty sipp scenario and attach it again.

BR, Bjoern

[Earn330]

You were right. The zip file was empty. So I attached this here again. I attached also my sems config

sipp_uas.zip
sems_config.zip

[juha-h]

Earn330 writes:

what do you mean with simple b2b? Is it documented somewhere? Are there examples for configuration.

There is ann_b2b application that could be modified to skip the announcement and then set set_sip_relay_only(true), That would cause INVITE to be relayed without answering. Same could be achieved by writing a DSM app that in invite transition calls B2B.connectCallee. I planned to try with something like that first in order to find out if the issue is sbc specific.

That call itself is relay only through SEMS. We need this to rewrite some ids to prevent our PSTN switch to drop the call in redirection cases. I will have a look at the empty sipp scenario and attach it again.

Also you could try with a DSM app instead of sbc.

…

-- Juha

[Earn330]

I had some thoughts about your ann_b2b proposal - this is not usable for us, as we use the sbc application with different profiles for in-, outbound and looped calls. These profiles are different as you can see in my config files. Maybe DSM is an option, but at the moment I'm not able to program scenarios with it.

[juha-h]

I gave your test a try using a simple b2bua dsm app. After CANCEL, the two call legs stayed alive (according to sems-list-active-calls) for about 3 minutes and then the events below happened and the both calls got cleared.

…

-- Juha Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [fire, sip_trans.cpp:206] DEBUG: Transaction timer expired: type=C, trans=0x7fdb14005c10, eta=29949, t=29949 Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [reset_timer, sip_trans.cpp:189] DEBUG: Clearing old timer of type C (this=0x7fdb0401aeb0) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [cancel, trans_layer.cpp:1418] DEBUG: Transaction has already been canceled Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [reset_timer, sip_trans.cpp:247] DEBUG: New timer of type BL at time=31549 (repeated=0) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:813] DEBUG: Received reply: 408 Timeout Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:814] DEBUG: reply.callid = <32A4D04C-5A1CBB2B0009F1B5-2D9D1700> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:815] DEBUG: reply.from_tag = <72ECEB21-5A1CBB2B0009F1B1-2D9D1700> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:816] DEBUG: reply.to_tag = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:817] DEBUG: reply.contact = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:818] DEBUG: reply.to_uri = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:819] DEBUG: cseq = <10> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:820] DEBUG: reply.route = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:821] DEBUG: hdrs = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:822] DEBUG: body-ct = <> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:828] DEBUG: ^^ M [32A4D04C-5A1CBB2B0009F1B5-2D9D1700|72ECEB21-5A1CBB2B0009F1B1-2D9D1700] ru SIP reply 408 Timeout handled ^^ Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [processingCycle, AmSession.cpp:347] DEBUG: vv S [32A4D04C-5A1CBB2B0009F1B5-2D9D1700|72ECEB21-5A1CBB2B0009F1B1-2D9D1700] Cancelling, stopped, 1 UACTransPending, 0 usages vv Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [process, AmSession.cpp:650] DEBUG: AmSession processing event Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onRxReply, AmBasicSipDialog.cpp:480] DEBUG: onRxReply(rep = 408 Timeout): transaction found! Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onRxReplyStatus, AmSipDialog.cpp:426] DEBUG: CANCEL accepted, status -> Disconnected Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [setStatus, AmBasicSipDialog.cpp:84] DEBUG: setting SIP dialog status: Cancelling->Disconnected Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onReplyIn, AmOfferAnswer.cpp:198] DEBUG: after 408 reply to INVITE: resetting OA state Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [setState, AmOfferAnswer.cpp:69] DEBUG: setting SIP dialog O/A status: OfferSent->None Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, DSMCall.cpp:994] DEBUG: onSipReply: 408 Timeout (fwd=1) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, DSMCall.cpp:995] DEBUG: onSipReply: content-type = Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, AmB2BSession.cpp:470] DEBUG: onSipReply: INVITE -> 408 Timeout (fwd=true), c-t= Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, AmB2BSession.cpp:492] DEBUG: relaying B2B SIP reply 408 Timeout Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [relayEvent, AmB2BSession.cpp:591] DEBUG: AmB2BSession::relayEvent: to other_id='050C1FD5-5A1CBB2B0009EF9C-2DED6700' Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [processingCycle, AmSession.cpp:416] DEBUG: ^^ S [32A4D04C-5A1CBB2B0009F1B5-2D9D1700|72ECEB21-5A1CBB2B0009F1B1-2D9D1700] Disconnected, stopped, 0 UACTransPending, 0 usages ^^ Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [run, AmSession.cpp:272] DEBUG: session event loop ended, finalizing session Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [finalize, AmSession.cpp:430] DEBUG: running finalize sequence... Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp engine]: STOP STREAM ID=3 mode=CLEAR state=ACTIVE. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp]: #011Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [destroy, AmSession.cpp:481] DEBUG: AmSession::destroy() Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [stop, AmThread.cpp:123] DEBUG: Thread 140579338782464 (140579338782464) calling on_stop, give it a chance to clean up. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [on_stop, AmSession.cpp:452] DEBUG: AmSession::stop() Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [clearAudio, AmSession.cpp:642] DEBUG: Audio cleared !!! Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [stop, AmThread.cpp:138] DEBUG: Thread 140579338782464 (140579338782464) finished detach. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [finalize, AmSession.cpp:444] DEBUG: session is stopped. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d8d0700] [_start, AmThread.cpp:77] DEBUG: Thread 140579338782464 is ending. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [processingCycle, AmSession.cpp:347] DEBUG: vv S [ffdcd846172f6179|050C1FD5-5A1CBB2B0009EF9C-2DED6700] Cancelling, stopped, 0 UACTransPending, 0 usages vv Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [process, DSMCall.cpp:485] DEBUG: DSMCall::process Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onB2BEvent, AmB2BSession.cpp:1047] DEBUG: 408 Timeout reply received from other leg Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onB2BEvent, AmB2BSession.cpp:1110] DEBUG: reply from callee: 408 Timeout Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onB2BEvent, AmB2BSession.cpp:176] DEBUG: AmB2BSession::onB2BEvent Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onB2BEvent, AmB2BSession.cpp:244] DEBUG: B2BSipReply: 408 Timeout (fwd=true) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onB2BEvent, AmB2BSession.cpp:246] DEBUG: B2BSipReply: content-type = Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [relaySip, AmB2BSession.cpp:873] DEBUG: relaying SIP reply 408 Timeout Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [reply, AmBasicSipDialog.cpp:615] DEBUG: reply: transaction found! Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onReplyOut, AmOfferAnswer.cpp:428] DEBUG: after 408 reply to INVITE: resetting OA state Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [setState, AmOfferAnswer.cpp:69] DEBUG: setting SIP dialog O/A status: OfferRecved->None Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [setStatus, AmBasicSipDialog.cpp:84] DEBUG: setting SIP dialog status: Cancelling->Disconnected Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [is_opt_set, transport.cpp:76] DEBUG: trsp_socket::socket_options = 0x0 Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [send_reply, trans_layer.cpp:413] DEBUG: reply_len = 523 Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [is_opt_set, transport.cpp:76] DEBUG: trsp_socket::socket_options = 0x0 Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [is_opt_set, transport.cpp:76] DEBUG: trsp_socket::socket_options = 0x0 Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [send_reply, trans_layer.cpp:588] DEBUG: Sending to 127.0.0.1:5070 <SIP/2.0 408 Timeout..Record-Route: <sip:127.0.0.1:...> Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [send, tcp_trsp.cpp:256] DEBUG: write event added... Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [update_uas_reply, trans_layer.cpp:2139] DEBUG: update_uas_reply(t=0x7fdb04011d10) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [reset_timer, sip_trans.cpp:247] DEBUG: New timer of type H at time=31549 (repeated=0) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onReplySent, AmB2BSession.cpp:545] DEBUG: relayed INVITE failed with 408 Timeout Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [onReplySent, AmB2BSession.cpp:547] DEBUG: recvd_req.erase(<27992,INVITE>) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [processingCycle, AmSession.cpp:416] DEBUG: ^^ S [ffdcd846172f6179|050C1FD5-5A1CBB2B0009EF9C-2DED6700] Disconnected, stopped, 0 UACTransPending, 0 usages ^^ Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [run, AmSession.cpp:272] DEBUG: session event loop ended, finalizing session Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [finalize, AmSession.cpp:430] DEBUG: running finalize sequence... Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp engine]: STOP STREAM ID=2 mode=CLEAR state=ACTIVE. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp]: #011Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [zrtp_log, AmZRTP.cpp:61] DEBUG: [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [runEvent, DSMStateEngine.cpp:616] DEBUG: o v DSM current state 'end', processing 'BeforeDestroy' event v Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [runEvent, DSMStateEngine.cpp:624] DEBUG: > state 'end' Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [runEvent, DSMStateEngine.cpp:630] DEBUG: ...checking transition 'bye recvd' Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [runEvent, DSMStateEngine.cpp:731] DEBUG: o ^ DSM event processed/consumed; current state 'end' ^ Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [destroy, AmSession.cpp:481] DEBUG: AmSession::destroy() Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [stop, AmThread.cpp:123] DEBUG: Thread 140579339835136 (140579339835136) calling on_stop, give it a chance to clean up. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [on_stop, AmSession.cpp:452] DEBUG: AmSession::stop() Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [clearAudio, AmSession.cpp:642] DEBUG: Audio cleared !!! Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [stop, AmThread.cpp:138] DEBUG: Thread 140579339835136 (140579339835136) finished detach. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [finalize, AmSession.cpp:444] DEBUG: session is stopped. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2d9d1700] [_start, AmThread.cpp:77] DEBUG: Thread 140579339835136 is ending. Nov 28 03:29:03 lohi sems[26342]: [#7fdb2ded6700] [on_write, tcp_trsp.cpp:431] DEBUG: on_write (connected = 1) Nov 28 03:29:03 lohi sems[26342]: [#7fdb2ded6700] [on_write, tcp_trsp.cpp:466] DEBUG: bytes written: <SIP/2.0 408 Timeout..Record-Route: <sip:127.0.0.1:5070;transport=tcp;r2=on;lr;n1;dm;as>..Record-Route: <sip:192.26.133.10;transport=tcp;r2=on;lr;n1;dm;as>..Via: SIP/2.0/TCP 127.0.0.1:5070;branch=z9hG4bKf8c1.776dc428d713db2ac36d0963f46a916e.0;i=5..Via: SIP/2.0/TCP 192.168.43.148:38587;received=192.26.133.10;branch=z9hG4bK9b08154a1d594f26;rport=35576..To: <sip:[email protected];appl=b2b-relay>..From: <sip:[email protected]>;tag=e845a48053f0d7c3..Call-ID: ffdcd846172f6179..CSeq: 27992 INVITE..Content-Length: 0....>

[juha-h]

I also tried with simple sbc profile: $ cat /etc/sems/opensipg.sbcprofile.conf call_control=$H(P-Call-Control) enable_session_timer=yes with INVITE headers P-App-Name: sbc. P-App-Param: profile=opensipg. P-Call-Control: ctl;From=Anonymous <sip:[email protected]>. and the test call (with only one leg remaining) got properly cleared again after about 3 minutes.

…

-- Juha # sems-list-active-calls Nov 28 03:44:21 lohi sems[26342]: [#7fdb2e7df700] [execute, XMLRPC2DI.cpp:496] DEBUG: XMLRPC2DI: calls = 1 Active calls: 1 Nov 28 03:44:21 lohi sems[26342]: [#7fdb2e7df700] [execute, XMLRPC2DI.cpp:574] DEBUG: XMLRPC2DI: factory 'monitoring' function 'listActive' [ '334A71A6-5A1CBEC200091549-2D9D1700', 'SystemDSM_2AAF2967-5A1CB98800096158-4001D740'] # sems-list-active-calls Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [fire, sip_trans.cpp:206] DEBUG: Transaction timer expired: type=C, trans=0x7fdb20004da0, eta=75896, t=75896 Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [reset_timer, sip_trans.cpp:189] DEBUG: Clearing old timer of type C (this=0x7fdb040171b0) Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [cancel, trans_layer.cpp:1418] DEBUG: Transaction has already been canceled Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [reset_timer, sip_trans.cpp:247] DEBUG: New timer of type BL at time=77496 (repeated=0) Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:813] DEBUG: Received reply: 408 Timeout Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:814] DEBUG: reply.callid = <4BD48DBD-5A1CBEC20009154C-2D9D1700> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:815] DEBUG: reply.from_tag = <334A71A6-5A1CBEC200091549-2D9D1700> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:816] DEBUG: reply.to_tag = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:817] DEBUG: reply.contact = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:818] DEBUG: reply.to_uri = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:819] DEBUG: cseq = <10> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:820] DEBUG: reply.route = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:821] DEBUG: hdrs = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:822] DEBUG: body-ct = <> Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e3db700] [handle_sip_reply, SipCtrlInterface.cpp:828] DEBUG: ^^ M [4BD48DBD-5A1CBEC20009154C-2D9D1700|334A71A6-5A1CBEC200091549-2D9D1700] ru SIP reply 408 Timeout handled ^^ Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [processingCycle, AmSession.cpp:347] DEBUG: vv S [4BD48DBD-5A1CBEC20009154C-2D9D1700|334A71A6-5A1CBEC200091549-2D9D1700] Cancelling, stopped, 1 UACTransPending, 0 usages vv Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [process, AmSession.cpp:650] DEBUG: AmSession processing event Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onRxReply, AmBasicSipDialog.cpp:480] DEBUG: onRxReply(rep = 408 Timeout): transaction found! Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onRxReplyStatus, AmSipDialog.cpp:426] DEBUG: CANCEL accepted, status -> Disconnected Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [setStatus, AmBasicSipDialog.cpp:84] DEBUG: setting SIP dialog status: Cancelling->Disconnected Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onReplyIn, AmOfferAnswer.cpp:198] DEBUG: after 408 reply to INVITE: resetting OA state Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [setState, AmOfferAnswer.cpp:69] DEBUG: setting SIP dialog O/A status: OfferSent->None Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, SBCCallLeg.cpp:621] DEBUG: onSipReply: 408 Timeout (fwd=1) Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, SBCCallLeg.cpp:622] DEBUG: onSipReply: content-type = Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, SessionTimer.cpp:145] DEBUG: erasing 10 from sent_requests Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, CallLeg.cpp:975] DEBUG: 334A71A6-5A1CBEC200091549-2D9D1700: SIP reply 408/10 INVITE (to relayed request) received in NoReply state Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [offerRejected, CallLeg.cpp:1640] DEBUG: 334A71A6-5A1CBEC200091549-2D9D1700: offer rejected! (hold status: 2) Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, AmB2BSession.cpp:470] DEBUG: onSipReply: INVITE -> 408 Timeout (fwd=true), c-t= Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onSipReply, AmB2BSession.cpp:492] DEBUG: relaying B2B SIP reply 408 Timeout Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [relayEvent, SBCCallLeg.cpp:483] DEBUG: filtering body for reply 'INVITE' (c/t '') Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [filterSdp, SBCCallLeg.cpp:1423] DEBUG: filtering body Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [relayEvent, AmB2BSession.cpp:591] DEBUG: AmB2BSession::relayEvent: to other_id='43DF40C7-5A1CBEC2000912EF-2DED6700' Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [updateCallStatus, CallLeg.cpp:1225] DEBUG: B leg 334A71A6-5A1CBEC200091549-2D9D1700 changing status from NoReply to Disconnected Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [bye, AmSipDialog.cpp:589] DEBUG: bye(): we are not connected (status=Disconnected). do nothing! Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [onTransFinished, CallLeg.cpp:1723] DEBUG: UAC/UAS transaction finished Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [processingCycle, AmSession.cpp:416] DEBUG: ^^ S [4BD48DBD-5A1CBEC20009154C-2D9D1700|334A71A6-5A1CBEC200091549-2D9D1700] Disconnected, stopped, 0 UACTransPending, 0 usages ^^ Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [run, AmSession.cpp:272] DEBUG: session event loop ended, finalizing session Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [finalize, AmSession.cpp:430] DEBUG: running finalize sequence... Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [destroy, AmSession.cpp:481] DEBUG: AmSession::destroy() Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [stop, AmThread.cpp:123] DEBUG: Thread 140579338782464 (140579338782464) calling on_stop, give it a chance to clean up. Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [on_stop, AmSession.cpp:452] DEBUG: AmSession::stop() Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [clearAudio, AmSession.cpp:642] DEBUG: Audio cleared !!! Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [stop, AmThread.cpp:138] DEBUG: Thread 140579338782464 (140579338782464) finished detach. Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [finalize, AmSession.cpp:444] DEBUG: session is stopped. Nov 28 03:44:22 lohi sems[26342]: [#7fdb2d8d0700] [_start, AmThread.cpp:77] DEBUG: Thread 140579338782464 is ending. Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e6de700] [execute, XMLRPC2DI.cpp:496] DEBUG: XMLRPC2DI: calls = 0 Active calls: 0 Nov 28 03:44:22 lohi sems[26342]: [#7fdb2e6de700] [execute, XMLRPC2DI.cpp:574] DEBUG: XMLRPC2DI: factory 'monitoring' function 'listActive' [ '334A71A6-5A1CBEC200091549-2D9D1700', 'SystemDSM_2AAF2967-5A1CB98800096158-4001D740'] # sems-list-active-calls Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:237] DEBUG: Thread watcher starting its work Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:248] DEBUG: thread 140579371988736 is to be processed in thread watcher. Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:254] DEBUG: thread 140579371988736 still running. Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:248] DEBUG: thread 140579369883392 is to be processed in thread watcher. Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:254] DEBUG: thread 140579369883392 still running. Nov 28 03:44:24 lohi sems[26342]: [#7fdb2f77a700] [run, AmThread.cpp:271] DEBUG: Thread watcher finished Nov 28 03:44:24 lohi sems[26342]: [#7fdb2e5dd700] [execute, XMLRPC2DI.cpp:496] DEBUG: XMLRPC2DI: calls = 0 Active calls: 0 Nov 28 03:44:24 lohi sems[26342]: [#7fdb2e5dd700] [execute, XMLRPC2DI.cpp:574] DEBUG: XMLRPC2DI: factory 'monitoring' function 'listActive' [ '334A71A6-5A1CBEC200091549-2D9D1700', 'SystemDSM_2AAF2967-5A1CB98800096158-4001D740'] # Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [clean_sessions, AmSessionContainer.cpp:77] DEBUG: Session cleaner starting its work Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [clean_sessions, AmSessionContainer.cpp:93] DEBUG: session [0x7fdb2d8d0700] has been destroyed Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [removeCall, SBCCallRegistry.cpp:78] DEBUG: SBCCallRegistry: removed entry for call '334A71A6-5A1CBEC200091549-2D9D1700' Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [~AmB2BSession, AmB2BSession.cpp:89] DEBUG: relayed_req.size() = 0 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [~AmB2BSession, AmB2BSession.cpp:92] DEBUG: recvd_req.size() = 0 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [removeTimer, AmSession.cpp:1253] DEBUG: removing timer -2 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [removeTimer, AmSession.cpp:1253] DEBUG: removing timer -1 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [dump, AmBasicSipDialog.cpp:765] DEBUG: callid = 4BD48DBD-5A1CBEC20009154C-2D9D1700 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [dump, AmBasicSipDialog.cpp:766] DEBUG: local_tag = 334A71A6-5A1CBEC200091549-2D9D1700 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [dump, AmBasicSipDialog.cpp:767] DEBUG: uac_trans.size() = 0 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [dump, AmBasicSipDialog.cpp:775] DEBUG: uas_trans.size() = 0 Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [~AmSession, AmSession.cpp:103] DEBUG: AmSession destructor finished Nov 28 03:44:27 lohi sems[26342]: [#7fdb3cf3d700] [run, AmSessionContainer.cpp:136] DEBUG: Session cleaner finished # sems-list-active-calls Nov 28 03:44:33 lohi sems[26342]: [#7fdb2e9e1700] [execute, XMLRPC2DI.cpp:496] DEBUG: XMLRPC2DI: calls = 0 Active calls: 0 Nov 28 03:44:33 lohi sems[26342]: [#7fdb2e9e1700] [execute, XMLRPC2DI.cpp:574] DEBUG: XMLRPC2DI: factory 'monitoring' function 'listActive' ['SystemDSM_2AAF2967-5A1CB98800096158-4001D740']

[Earn330]

This is definitly not the same that happens here. Instead of deleting the call from AmSession it remains there with a repeating log message. I attached it here. What version are you using?
Me it's this one on Debian Jessie

root@voip-lab-proxy:~/sipp_uas# sems -v
Sip Express Media Server (1.5.0-49-gd756ee2 (x86_64/linux))

sems_debug_uacTransPending.log

[juha-h]

Earn330 writes:

This is definitly not the same that happens here. Instead of deleting the call from AmSession it remains there with a repeating log message. I attached it here. What version are you using?

I'm using latest master from git on Debian Stretch. Try with the simple sbc config that I showed, i.e., does the problem appear with it in your environment.

…

-- Juha

[Earn330]

I think I'll close this, as with the latest 1.7 the reported problem can't be reproduced. But don't worry, things got worse as you will see in the next ticket