search

SIPp / pysipp

SIPp for Humans - launch multiple agents with Python
GNU General Public License v2.0
179 stars 55 forks source link

Error logging output is easy to miss.. we should repair the formatting output. #78

Closed pablodz closed 2 years ago

pablodz commented 2 years ago

Hello there,

First of all, thanks for a great framework. I want to test a call like a client from a softphone call. I tried unsuccesfully with

import pysipp

pysipp.client(
    destaddr=("mydomain.com", 5060), 
    auth_username="myuser",
    auth_password="mypassword",
    extension="999"
)()

Those params are what I need to make a call, I'm getting this log, what am I doing wrong?

gdp@gdp:~/Downloads/ddossip$ python3 main.py 
stderr for 'uac' @ None
b'Resolving remote host \'mydomain.com\'... Done.\n2022-05-26\t14:02:34.792872\t1653591754.792872: Aborting call on unexpected message for Call-Id \'1-84371@192.168.1.43\': while expecting \'180\' (index 2), received \'SIP/2.0 407 Proxy Authentication Required\r\nVia: SIP/2.0/UDP 192.168.1.43:5060;rport=32607;received=181.67.169.200;branch=z9hG4bK-84371-1-0\r\nFrom: sipp <sip:sipp@192.168.1.43:5060>;tag=84371SIPpTag001\r\nTo: service <sip:service@34.236.226.185:5060>;tag=jcQ7pFe9QNvZD\r\nCall-ID: 1-84371@192.168.1.43\r\nCSeq: 1 INVITE\r\nUser-Agent: ExampleAgent\r\nAccept: application/sdp\r\nAllow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, PRACK, NOTIFY, PUBLISH, SUBSCRIBE\r\nSupported: precondition, 100rel, path, replaces\r\nAllow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer\r\nProxy-Authenticate: Digest realm="192.168.1.43", nonce="43d1660c-1a8f-40f2-b2ff-ffed14096255", algorithm=MD5, qop="auth"\r\nContent-Length: 0\r\n\r\n\'\n'

'screen_file' contents for 'uac' @ None:
------------------------------ Scenario Screen -------- [1-9]: Change Screen --
  Call rate (length)   Port   Total-time  Total-calls  Remote-host
  1.0(0 ms)/1.000s   5060       1.11 s            1  34.236.226.85:5060(UDP)

  Call limit 1 hit, 0.0 s period          0 ms scheduler resolution            
  0 calls (limit 1)                       Peak was 1 calls, after 1 s
  0 Running, 4 Paused, 4 Woken up
  0 dead call msg (discarded)             0 out-of-call msg (discarded)
  0 open sockets                          0/0/0 UDP errors (send/recv/cong)

                                 Messages  Retrans   Timeout   Unexpected-Msg
0 :      INVITE ---------->         1         0         0                      
1 :         100 <----------         1         0         0         0            
2 :         180 <----------         0         0         0         1            
3 :         183 <----------         0         0         0         0            
4 :         200 <----------  E-RTD1 0         0         0         0            
5 :         ACK ---------->         0         0                                
6 :       Pause [      0ms]         0                             0        
7 :         BYE ---------->         0         0         0                      
8 :         200 <----------         0         0         0         0            

Last Error: Aborting call on unexpected message for Call-Id '1-84371@192...
------- Waiting for active calls to end. Press [q] again to force exit. -------
----------------------------- Statistics Screen ------- [1-9]: Change Screen --
  Start Time             | 2022-05-26   14:02:33.676882 1653591753.676882         
  Last Reset Time        | 2022-05-26   14:02:34.792967 1653591754.792967         
  Current Time           | 2022-05-26   14:02:34.793001 1653591754.793001         
-------------------------+---------------------------+--------------------------
  Counter Name           | Periodic value            | Cumulative value
-------------------------+---------------------------+--------------------------
  Elapsed Time           | 00:00:00:000000           | 00:00:00:000000          
  Call Rate              |    0.000 cps              |    0.896 cps             
-------------------------+---------------------------+--------------------------
  Incoming calls created |        0                  |        0                 
  Outgoing calls created |        0                  |        1                 
  Total Calls created    |                           |        1                 
  Current Calls          |        0                  |                          
-------------------------+---------------------------+--------------------------
  Successful call        |        0                  |        0                 
  Failed call            |        0                  |        1                 
-------------------------+---------------------------+--------------------------
  Response Time 1        | 00:00:00:000000           | 00:00:00:000000          
  Call Length            | 00:00:00:000000           | 00:00:00:000000          
Last Error: Aborting call on unexpected message for Call-Id '1-84371@192...
------- Waiting for active calls to end. Press [q] again to force exit. -------
---------------------------- Repartition Screen ------- [1-9]: Change Screen --
  Average Response Time Repartition 1                                          
             0 ms <= n <         10 ms :          0
            10 ms <= n <         20 ms :          0
            20 ms <= n <         30 ms :          0
            30 ms <= n <         40 ms :          0
            40 ms <= n <         50 ms :          0
            50 ms <= n <        100 ms :          0
           100 ms <= n <        150 ms :          0
           150 ms <= n <        200 ms :          0
                   n >=        200 ms :          0
  Average Call Length Repartition                                              
             0 ms <= n <         10 ms :          0
            10 ms <= n <         50 ms :          0
            50 ms <= n <        100 ms :          0
           100 ms <= n <        500 ms :          1
           500 ms <= n <       1000 ms :          0
          1000 ms <= n <       5000 ms :          0
          5000 ms <= n <      10000 ms :          0
                   n >=      10000 ms :          0
Last Error: Aborting call on unexpected message for Call-Id '1-84371@192...
------- Waiting for active calls to end. Press [q] again to force exit. -------

Traceback (most recent call last):
  File "/home/gdp/Downloads/ddossip/main.py", line 3, in <module>
    pysipp.client(
  File "/home/gdp/.local/lib/python3.10/site-packages/pysipp/agent.py", line 72, in __call__
    return plugin.mng.hook.pysipp_run_protocol(
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/hooks.py", line 289, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/manager.py", line 68, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/manager.py", line 59, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/callers.py", line 208, in _multicall
    return outcome.get_result()
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/callers.py", line 80, in get_result
    raise ex[1].with_traceback(ex[2])
  File "/home/gdp/.local/lib/python3.10/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/gdp/.local/lib/python3.10/site-packages/pysipp/__init__.py", line 250, in pysipp_run_protocol
    finalize(cmds2procs, raise_exc=raise_exc)
  File "/home/gdp/.local/lib/python3.10/site-packages/pysipp/__init__.py", line 228, in finalize
    raise SIPpFailure(msg)
pysipp.SIPpFailure: Some agents failed
'uac' with exit code 1 -> At least one call failed
goodboy commented 2 years ago

it's in your logging output amigo:

Last Error: Aborting call on unexpected message for Call-Id '1-84371@192... while expecting \'180\' (index 2), received \'SIP/2.0 407 Proxy Authentication Required\r\nVia: ...

you can see it in the flow diagram as well, where it's expecting a provisional response and your server returns an unexpected msg.

looks like the server side isn't expecting the info you're sending to it and requires some auth 😉

goodboy commented 2 years ago

Actually, you probably missed it because it looks like the logging output isn't really being formatted nicely for console, we should probably fix that 😂