MonoTime is not being used for credit-time, expires and np_expires

[twmobius]

I've been trying to use sippy with radius support but I am facing an issue with MonoTime implementation.

It seems that if a route returned from radius which contains credit-time, expires and np_expires parameters those are being cast as ints and when passed to a MonoAbsTimeout object, b2bua throws an exception that mtime is not MonoTime. I am guessing similar issues might exist with max_credit_time and similar global variables.

b2bua/sippy/Time/Timeout.py

Line 45 in 8adb5f9

raise TypeError('mtime is not MonoTime')

I've thought of doing something simple like

if isinstance(mtime, float):
    mtime = (MonoTime()) + mtime

but it didn't work. I'm trying to resolve this myself, but I haven't yet understood the source code with regards to Time objects and any help would be greatly appreciated.

@sobomax Thank you for the work you've done on Sippy!

[twmobius]

Just a quick update. The MonoTime implementation seems incomplete since I've come against a related error in RadiusAccounting.py as well. There might be more but I haven't found them yet.

Applying the following two patches seems to fix the issue:

diff --git a/sippy/Time/Timeout.py b/sippy/Time/Timeout.py
index 1f0c103..eef98b8 100644
--- a/sippy/Time/Timeout.py
+++ b/sippy/Time/Timeout.py
@@ -41,8 +41,12 @@ def TimeoutInact(timeout_cb, ival, nticks = 1, *cb_params):
     return ED2.regTimer(timeout_cb, ival, nticks, False, *cb_params)

 def TimeoutAbsMono(timeout_cb, mtime, *cb_params):
+    if isinstance(mtime, int) or isinstance(mtime, float):
+        mtime = MonoTime(monot=mtime)
+
     if not isinstance(mtime, MonoTime):
         raise TypeError('mtime is not MonoTime')
     el = ED2.regTimer(timeout_cb, mtime, None, True, *cb_params)
     el.go()
     return el

diff --git a/sippy/RadiusAccounting.py b/sippy/RadiusAccounting.py
index 4853e5b..adc0f86 100644
--- a/sippy/RadiusAccounting.py
+++ b/sippy/RadiusAccounting.py
@@ -26,7 +26,7 @@
 # SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

 from time import time, strftime, gmtime
-from sippy.Time.Timeout import Timeout
+from sippy.Time.Timeout import Timeout, MonoTime

 sipErrToH323Err = {400:('7f', 'Interworking, unspecified'), 401:('39', 'Bearer capability not authorized'), \
   402:('15', 'Call rejected'), 403:('39', 'Bearer capability not authorized'), 404:('1', 'Unallocated number'), \
@@ -167,6 +167,9 @@ class RadiusAccounting(object):
         self.global_config['_radius_client'].do_acct(attributes, self._process_result, self.sip_cid, time())

     def ftime(self, t):
+        if isinstance(t, MonoTime):
+            return t.ftime()
+
         gt = gmtime(t)
         day = strftime('%d', gt)
         if day[0] == '0':

It seems that there is code in some parts that expects floats while at other parts expects MonoTime. However I am not entirely sure especially if the first patch is correct, since I am passing the float value to MonoTime's monot argument, which seems to always be a float. However it feels like a workaround and I am not sure if it will cause issues down the line.

Could someone help me verify this, and I could submit a PR for both

[sobomax]

Hey @twmobius thanks for the follow-up. In general accepting "float" into TimeoutAbsMono() is a wrong direction and a good way to shoot oneself into the foot just masking actual error, since most likely it's just a duration, not really montonic time (i.e. system uptime), so it would just result in the timer far in the past. This check is designed to catch mistakes like this!

If you look at the code in UA.startCreditTimer, it explicitly converts from credit_time supplied by the upper layer(s) into MonoTime() by adding it into rtime:

    def startCreditTimer(self, rtime): #<-rtime is instance of MonoTime
        if self.credit_time != None:
            self.credit_times[0] = rtime + self.credit_time  #<-self.credit_times[0] is instance of MonoTime too now
            self.credit_time = None
        try:
            credit_time = min([x for x in self.credit_times.values() if x != None])
        except ValueError:
            return
        self.credit_timer = TimeoutAbsMono(self.credit_expires, credit_time, credit_time)

Now to actually fix the issue properly I am having a bit of hard time understanding where it happens. Would you mind posting a full traceback leading to hitting this:

raise TypeError('mtime is not MonoTime')

And we go from there. Thanks!

[twmobius]

Hey @sobomax, thanks for the reply. I was afraid I was alone on this. I totally agree with you, it seemed hackish. The thing is that the issue occurs at credit-time, expires and np_expires

I am attaching the radius response Routing commands and their matching exceptions:

h323-ivr-in=Routing:123@192.168.5.104;credit-time=7200;expires=15;np_expires=5

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/sippy/External_command.py", line 144, in process_result
    result_callback(result, *callback_parameters)
  File "/usr/local/lib/python2.7/dist-packages/sippy/RadiusAuthorisation.py", line 68, in _process_result
    res_cb(results)
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 282, in rDone
    self.placeOriginate(self.routes.pop(0))
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 340, in placeOriginate
    self.uaO.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UA.py", line 214, in recvEvent
    newstate = self.state.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UacStateIdle.py", line 95, in recvEvent
    self.ua.no_progress_timer = TimeoutAbsMono(self.ua.no_progress_expires, self.ua.no_progress_time)
  File "/usr/local/lib/python2.7/dist-packages/sippy/Time/Timeout.py", line 47, in TimeoutAbsMono
    raise TypeError('mtime is not MonoTime')
TypeError: mtime is not MonoTime

h323-ivr-in=Routing:123@192.168.5.104;credit-time=7200;expires=15

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/sippy/External_command.py", line 144, in process_result
    result_callback(result, *callback_parameters)
  File "/usr/local/lib/python2.7/dist-packages/sippy/RadiusAuthorisation.py", line 68, in _process_result
    res_cb(results)
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 282, in rDone
    self.placeOriginate(self.routes.pop(0))
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 340, in placeOriginate
    self.uaO.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UA.py", line 214, in recvEvent
    newstate = self.state.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UacStateIdle.py", line 97, in recvEvent
    self.ua.expire_timer = TimeoutAbsMono(self.ua.expires, self.ua.expire_time)
  File "/usr/local/lib/python2.7/dist-packages/sippy/Time/Timeout.py", line 47, in TimeoutAbsMono
    raise TypeError('mtime is not MonoTime')
TypeError: mtime is not MonoTime

h323-ivr-in=Routing:123@192.168.5.104;credit-time=7200

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/sippy/Udp_server.py", line 257, in handle_read
    self.uopts.data_callback(data, address, self, rtime)
  File "/usr/local/lib/python2.7/dist-packages/sippy/SipTransactionManager.py", line 300, in handleIncoming
    self.incomingResponse(resp, t, checksum)
  File "/usr/local/lib/python2.7/dist-packages/sippy/SipTransactionManager.py", line 483, in incomingResponse
    t.resp_cb(msg, t)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UA.py", line 202, in recvResponse
    newstate = self.state.recvResponse(resp, tr)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UacStateTrying.py", line 132, in recvResponse
    self.ua.startCreditTimer(resp.rtime)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UA.py", line 414, in startCreditTimer
    self.credit_timer = TimeoutAbsMono(self.credit_expires, credit_time, credit_time)
  File "/usr/local/lib/python2.7/dist-packages/sippy/Time/Timeout.py", line 47, in TimeoutAbsMono
    raise TypeError('mtime is not MonoTime')
TypeError: mtime is not MonoTime

The function you've mentioned provided me with the hint I was missing to figure this out. It seems that self.credit_times[0] is actually not a MonoTime since __add__() method in MonoTime returns a float:

b2bua/sippy/Time/MonoTime.py

Line 126 in 8adb5f9

return (self.monot + x)

Similarly this is the case with all operation method calls (__sub__, __radd__, __rsub__)

And if you look at RadiusAccounting.py

b2bua/sippy/RadiusAccounting.py

Line 156 in 8adb5f9

attributes.extend((('h323-connect-time', self.ftime(self.iTime + delay)), ('h323-setup-time', self.ftime(self.iTime)), \

the self.ftime(self.iTime + delay)) was working, since self.iTime + delay was a float being passed to self.ftime which was expecting a float, but at the same time the self.ftime(self.iTime) was causing an exception because self.iTime was a MonoTime.

So after changing the operations of MonoTime to return a MonoTime I had to tweak RadiusAccounting here and there to make it work. This is the complete patch:

Index: sippy/Time/MonoTime.py
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- sippy/Time/MonoTime.py	(revision 8adb5f92a86c7f97122e9613a8ee3022bea83c9e)
+++ sippy/Time/MonoTime.py	(date 1603444232432)
@@ -121,24 +121,20 @@
         return strftime('%%H:%%M:%%S.000 GMT %%a %%b %s %%Y' % day, gt)
 
     def __add__(self, x):
-        if isinstance(x, MonoTime):
-            return (self.monot + x.monot)
-        return (self.monot + x)
+        offset = x.monot if isinstance(x, MonoTime) else x
+
+        return MonoTime(monot=self.monot + offset)
 
     def __sub__(self, x):
-        if isinstance(x, MonoTime):
-            return (self.monot - x.monot)
-        return (self.monot - x)
+        offset = x.monot if isinstance(x, MonoTime) else x
+
+        return MonoTime(monot=self.monot - offset)
 
     def __radd__(self, x):
-        if isinstance(x, MonoTime):
-            return (self.monot + x.monot)
-        return (self.monot + x)
+        return self.__add__(x)
 
     def __rsub__(self, x):
-        if isinstance(x, MonoTime):
-            return (x.monot - self.monot)
-        return (x - self.monot)
+        return self.__sub__(x)
 
     def __cmp__(self, other):
         if other == None:
Index: sippy/RadiusAccounting.py
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- sippy/RadiusAccounting.py	(revision 8adb5f92a86c7f97122e9613a8ee3022bea83c9e)
+++ sippy/RadiusAccounting.py	(date 1603444232433)
@@ -26,7 +26,7 @@
 # SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 from time import time, strftime, gmtime
-from sippy.Time.Timeout import Timeout
+from sippy.Time.Timeout import Timeout, MonoTime
 
 sipErrToH323Err = {400:('7f', 'Interworking, unspecified'), 401:('39', 'Bearer capability not authorized'), \
   402:('15', 'Call rejected'), 403:('39', 'Bearer capability not authorized'), 404:('1', 'Unallocated number'), \
@@ -130,6 +130,12 @@
             delay = self.cTime - self.iTime
             connected = True
         if not(self.ms_precision):
+            if isinstance(duration, MonoTime):
+                duration = duration.monot
+
+            if isinstance(delay, MonoTime):
+                delay = delay.monot
+
             duration = round(duration)
             delay = round(delay)
         attributes = self._attributes[:]
@@ -167,6 +173,9 @@
         self.global_config['_radius_client'].do_acct(attributes, self._process_result, self.sip_cid, time())
 
     def ftime(self, t):
+        if isinstance(t, MonoTime):
+            return t.frtime()
+
         gt = gmtime(t)
         day = strftime('%d', gt)
         if day[0] == '0':

I am still not exactly sure, if there are other places where floats are being expected and MonoTime is returned. I made a few test calls and they worked all the way, (both authorization and accounting) but I haven't spend that much time on the code to be 100% sure. If you feel that this patch is enough I am happy to provide you with a PR

[sobomax]

@twmobius thanks, that's sufficient amount of information for now. I am working on a reproducing the issue here:

https://travis-ci.com/github/sippy/voiptests/builds/192232824

Stay tuned.

[sobomax]

@twmobius ideed the crash is easily reproducible: https://travis-ci.com/github/sippy/voiptests/jobs/405739060#L2371

Working on a fix.

[twmobius]

@sobomax great! Just keep in mind that the --static_route="localhost:5062;ash=SIP-Hello1%3A%20World%21;ash=SIP-Hello2%3A%20World%21;credit_time=300;expires=299;np_expires=298" test will only crash on np_expires related code, and will not go into expires or credit_time since it's the first to be evaluated.

[twmobius]

Sorry to bother you, but take the time to check also with --acct_enable=on since I think there is an issue in RadiusAccounting.py as well. (check the diffs I've added in my previous comment)

[sobomax]

@twmobius fixes for all 4 timers and RadiusAccounting have landed. I'd appreciate if you run latest code revision 1688c9a or later and report if any other tracebacks are observed. Thanks!

[twmobius]

@sobomax I've tried with all three routing responses I've mentioned before and it works properly every time. The timers in the Accounting Stop appear also to be ok. Thank you very much!!

For reference:

24 Oct 19:04:35.141/ef07c087-399dd991@192.168.1.117/b2bua: sending Acct Stop (Originate):
h323-call-origin                 = 'originate'
h323-call-type                   = 'VoIP'
h323-session-protocol            = 'sipv2'
User-Name                        = '192.168.1.117'
Calling-Station-Id               = '456'
Called-Station-Id                = '123'
h323-conf-id                     = '8E9CCFAC E3FFF447 5AF54A78 FD88D1E6'
call-id                          = 'ef07c087-399dd991@192.168.1.117'
Acct-Session-Id                  = 'ef07c087-399dd991@192.168.1.117'
h323-remote-address              = '192.168.5.104'
h323-voice-quality               = '0'
Acct-Terminate-Cause             = 'User-Request'
h323-disconnect-time             = '19:04:34.000 GMT Sat Oct 24 2020'
Acct-Session-Time                = '4'
h323-disconnect-cause            = '10'
release-source                   = '2'
h323-connect-time                = '19:04:30.000 GMT Sat Oct 24 2020'
h323-setup-time                  = '19:04:30.000 GMT Sat Oct 24 2020'
Acct-Status-Type                 = 'Stop'
h323-ivr-out                     = 'sip_ua:Asterisk PBX 14.6.1'
provisional-timepoint            = '19:04:30.000 GMT Sat Oct 24 2020'

The only other traceback that I've been getting, but its unrelated to this ticket, is actually the one reported on #30 and it's the following:

----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/sippy/External_command.py", line 144, in process_result
    result_callback(result, *callback_parameters)
  File "/usr/local/lib/python2.7/dist-packages/sippy/RadiusAuthorisation.py", line 68, in _process_result
    res_cb(results)
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 278, in rDone
    self.placeOriginate(self.routes.pop(0))
  File "/usr/local/lib/python2.7/dist-packages/sippy/b2bua_radius.py", line 337, in placeOriginate
    self.uaO.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UA.py", line 214, in recvEvent
    newstate = self.state.recvEvent(event)
  File "/usr/local/lib/python2.7/dist-packages/sippy/UacStateIdle.py", line 75, in recvEvent
    laddress = self.ua.source_address, cb_ifver = 2, compact = self.ua.compact_sip)
  File "/usr/local/lib/python2.7/dist-packages/sippy/SipTransactionManager.py", line 358, in newTransaction
    t.data = msg.localStr(*t.userv.uopts.getSIPaddr(), compact = t.compact)
  File "/usr/local/lib/python2.7/dist-packages/sippy/SipMsg.py", line 169, in localStr
    mbody = self.body.localStr(local_addr, local_port)
  File "/usr/local/lib/python2.7/dist-packages/sippy/MsgBody.py", line 62, in localStr
    return self.content.localStr(local_addr, local_port)
AttributeError: 'unicode' object has no attribute 'localStr'
----------------------------------------------------------------------

As suggested in #30 I've modified MsgBody.py as such:

     https://ubuntu.com/livepatch
diff --git a/sippy/MsgBody.py b/sippy/MsgBody.py
index 0f9b9c7..56286fb 100644
--- a/sippy/MsgBody.py
+++ b/sippy/MsgBody.py
@@ -59,6 +59,9 @@ class MsgBody(object):
     def localStr(self, local_addr = None, local_port = None):
         if type(self.content) == str:
             return self.content
+        elif isinstance(self.content, unicode):
+            return str(self.content)
+
         return self.content.localStr(local_addr, local_port)

     def getType(self):

to get around this.