Every second call is waiting for server response

[TWinand]

femtosip/femtosip.py

Line 617 in 8d8a3a2

elif now - state['last_request'] > timeout:

Something must be wrong with this calculation because every second call the result is over 1.0 and the call was not triggered.
In an old version it work fine.

[Thommes17]

While I was using an older version for quite a while without issues, thanky you very much for the nice code!
However, I faced the same issue after updating to the latest version.

In my case, the log for a successful call looks like this:
INFO:femtosip:request: INVITE sip:[email protected]
INFO:femtosip:response: SIP/2.0 401 Unauthorized
INFO:femtosip:request: INVITE sip:[email protected]
INFO:femtosip:response: SIP/2.0 100 Trying
INFO:femtosip:response: SIP/2.0 183 Session Progress
INFO:femtosip:request: CANCEL sip:[email protected]
INFO:femtosip:response: SIP/2.0 487 Request Cancelled

While every second call return this log:
INFO:femtosip:request: INVITE sip:[email protected]
INFO:femtosip:response: IP/2.0 200 OK
INFO:femtosip:Timeout waiting for server response, trying to cancel call
INFO:femtosip:request: CANCEL sip:[email protected]
INFO:femtosip:response: SIP/2.0 481 Call Leg/Transaction Does Not Exist
ERROR:femtosip:Unhandled error.

It seems that the "IP/2.0 200 OK" is not read from the buffer after cancelling the call causing the timeout every second call. However, after some trying, I could not really locate the error in the code and switched back to the old version.

By the way, I am using Python 3.10 under Raspbian.

Cheers

[astoeckel]

Sorry for the late response. I guess that this commit is the culprit:

c5abc8c

I had to make that change because I suddenly had issues with packet fragmentation in my network.

I've reverted this commit in the timeout_experiment branch:

https://github.com/astoeckel/femtosip/tree/timeout_experiment

Could you see whether the problem exists there as well?

[Thommes17]

Thanks for the response!
I tested the code, however, the issue still persists that some calls are not cancelled properly and cause a permanent ringing of the phones.

But I played a bit with the code to try to figure things out:

The problem seems to be caused by the readout of the Sip Code 183
When everything is working, the log will read:

INFO:femtosip:response: SIP/2.0 183 Session Progress)

However, in some cases, the return is not read correctly resulting, e.g., in such a result:

ERROR:femtosip:Received invalid response code
INFO:femtosip:response: 490 -1 (Sep 1 2023)
ERROR:femtosip:Timeout while waiting for server response

Even though the call was initiated properly, it is not cancelled due to the timeout handling.
Thus, in my fork, I added a part that will try to cancel a potential active call in case of the timeout which will solve the infinitely ringing phones.

However, to try and solve the underlying issue, I stored some more information in the logfile, i.e., the actual read back code, protocol, message, and body.

If read correctly, the result is:

Code: 183

Protocol: SIP/2.0

Message: Session Progress

Body: v=0
o=user IN IP4 192.168.178.1
s=call
c=IN IP4 192.168.178.1
t=0 0
m=audio 7078 RTP/AVP 8 0 2 102 100 99 97 101
a=sendrecv
a=rtpmap:2 G726-32/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:7079

In the error cases, the results slightly vary, but basically the code, protocol, and message somehow contain information on the Fritzbox software version (7.57 from Sep. 2023 in my case):

Code:(Sep

Protocol: 113.07.57

Message: 1 2023)

Body: v=0
o=user IN IP4 192.168.178.1
s=call
c=IN IP4 192.168.178.1
t=0 0
m=audio 7078 RTP/AVP 8 0 2 102 100 99 97 101
a=sendrecv
a=rtpmap:2 G726-32/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:7079

I am happy for any hints on what could possibly cause this issue and how to solve it.

Best regards,
Thomas