Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

2024-04-18 14:07:19.359175 1713442039.359175: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 3. Retrying... There were more errors, enable -trace_err to log them #719

Open
Ambal17 opened this issue Apr 18, 2024 · 7 comments
Open

2024-04-18 14:07:19.359175 1713442039.359175: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 3. Retrying... There were more errors, enable -trace_err to log them #719

Ambal17 opened this issue Apr 18, 2024 · 7 comments

Comments

@Ambal17
Copy link

Ambal17 commented Apr 18, 2024

I am doing SIPP TLS traffic test for Alcatel Oxe pabx . SIPP Version Sipp 3.7.2

SIPP1 ---- pabx -- SIPP 2

TLS hand shake between SIPP1 to pabx is ok but pbx to SIPP2 is not ok.

When Pbx sending hello message SIPP 2 send handshake failure. i have verified the protocol it is TLS 1.2 both sides
encrpt.txt
@NikolayShakin
Copy link

Have the same error

@hamid-elaosta
Copy link

I'm having a similar issue; if I set -max_socket 10 it seems to be ok. If I use a larger number, or the default, most of the connections fail until all of the sockets have been created (when it shows "X open sockets"), then everything works fine.

I'm not sure why it takes so long but opening 50 sockets takes about 5-6 minutes on my end.

@Failxxx
Copy link

Failxxx commented May 23, 2024 •
edited
Loading

EDIT

I forgot to set the port after <server_ip_address>. So setting <server_ip_address>:5061 worked.

Issue

I am facing a similar issue.
Version: SIPp v3.7.2-57-ga0fce4c-TLS-SHA256
OS: Ubuntu 23.10, OpenSSL 3.0.10 1 Aug 2023 (Library: OpenSSL 3.0.10 1 Aug 2023)

cacert.pem and cakey.pem generated using the following command (found here): openssl req -newkey rsa:2048 -x509 -keyout cakey.pem -out cacert.pem -days 3650 -nodes

Here are the logs:

The following events occurred:
2024-05-23	17:46:26.502426	1716479186.502426: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-05-23	17:46:26.702932	1716479186.702932: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 2. Retrying...
2024-05-23	17:46:26.903486	1716479186.903486: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 3. Retrying...
2024-05-23	17:46:27.104093	1716479187.104093: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 4. Retrying...
2024-05-23	17:46:27.304489	1716479187.304489: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 5. Retrying...
2024-05-23	17:46:27.504763	1716479187.504763: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 6. Retrying...
2024-05-23	17:46:27.704980	1716479187.704980: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 7. Retrying...
2024-05-23	17:46:27.905108	1716479187.905108: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 8. Retrying...
2024-05-23	17:46:28.105464	1716479188.105464: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 9. Retrying...
2024-05-23	17:46:28.305848	1716479188.305848: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 10. Retrying...
2024-05-23	17:46:28.506085	1716479188.506085: Error in SSL connection: SSL I/O function returned SSL_ERROR_WANT_WRITE
2024-05-23	17:46:28.506219	1716479188.506219: Unable to connect a TCP/SCTP/TLS socket, errno = 11 (Resource temporarily unavailable)

I am running sipp <server_ip_address> -sf uac.sipp-scenario.xml -inf users.csv -i 10.0.0.69 -p 5061 -mp 9020 -t ln -m 1 -r 10 -l 200 -d 90000 -max_socket 1024 -trace_msg -trace_err -trace_logs

First steps of my scenario:

  <send retrans="500">
    <![CDATA[

      REGISTER sip:[field3] SIP/2.0
      Via: SIP/2.0/[transport] [local_ip]:[local_port]
      From: <sip:[field1]@[field3]>;tag=[pid]SIPpTag01[call_number]
      To: <sip:[field1]@[field3]>
      Contact: <sip:[field1]@[field5]:[local_port];transport=[transport]>
      Expires: 3600
      Call-ID: [call_id]
      CSeq: 20 REGISTER
      Content-Length: 0

    ]]>
  </send>

  <recv response="100" optional="true">
  </recv>

  <!-- Sometimes their server immediately answers "403 authentication failed" to our register request, then stop the scenario -->
  <recv response="403" optional="true" next="1">
  </recv>

  <recv response="401" auth="true">
  </recv>

I do not know what could be wrong.

@nttranbao
Copy link

nttranbao commented Jun 19, 2024 •
edited
Loading

Similar/same issue... even with setting the port... Call was ok, but at very low one-digit rate

SIPp version

 SIPp v3.7.2-57-ga0fce4c-TLS-SCTP-PCAP-SHA256.

Resolving remote host '172.16.0.1'... Done.
------------------------------ Scenario Screen -------- [1-9]: Change Screen --
  Call rate (length)   Port   Total-time  Total-calls  Remote-host
  10.0(5 ms)/1.000s   5060       5.12 s           10  172.16.0.1:5061(TLS)

  Call limit 10 hit, 184467440737095520.  18446744073709551614 ms scheduler res
  0 calls (limit 30)                      Peak was 10 calls, after 3 s
  0 Running, 8 Paused, 0 Woken up
  0 dead call msg (discarded)             0 out-of-call msg (discarded)
  0 open sockets                          0/0/0 TLS errors (send/recv/cong)
  0 Total RTP pckts sent                  0.000 last period RTP rate (kB/s)

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

------------------------------ Test Terminated --------------------------------
----------------------------- Statistics Screen ------- [1-9]: Change Screen --
  Start Time             | 2024-06-19   12:15:30.085254 1718813730.085254
  Last Reset Time        | 2024-06-19   12:15:35.217096 1718813735.217096
  Current Time           | 2024-06-19   12:15:35.217223 1718813735.217223
-------------------------+---------------------------+--------------------------
  Counter Name           | Periodic value            | Cumulative value
-------------------------+---------------------------+--------------------------
  Elapsed Time           | 00:00:00:000000           | 00:00:00:000000
  Call Rate              |    0.000 cps              |    1.949 cps
-------------------------+---------------------------+--------------------------
  Incoming calls created |        0                  |        0
  Outgoing calls created |        0                  |       10
  Total Calls created    |                           |       10
  Current Calls          |        0                  |
-------------------------+---------------------------+--------------------------
  Successful call        |        0                  |       10
  Failed call            |        0                  |        0
-------------------------+---------------------------+--------------------------
  Response Time 1        | 00:00:00:000000           | 00:00:00:000000
  Call Length            | 00:00:00:000000           | 00:00:00:000000
------------------------------ Test Terminated --------------------------------
2024-06-19      12:15:35.206793 1718813735.206793: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...

UAS

sipp -t ln -sn uas -i 172.16.0.1 -p 5061 -max_recv_loops 10000 -max_sched_loops 10000 -max_socket 100 -watchdog_major_maxtriggers 1000 -watchdog_major_maxtriggers 10000

UAC

sipp -i 172.16.0.2 -t ln -d 5 -sn uac 172.16.0.1:5061 -r 10 -m 10000 -max_recv_loops 10000 -max_sched_loops 10000 -max_socket 100 -watchdog_major_maxtriggers 1000 -watchdog_major_maxtriggers 10000 -m 10

On the other hand, to compare, I use tls_perf to test max TLS handshakes, and was able to get around 10,000 TLS handshake per second against NGINX/APACHE

root@linux:~/dev/load-tests/btc# tls-perf -T 10 -l 100 -t 8 --tls 1.2 172.16.0.1 8443
Running TLS benchmark with following settings:
Host:        172.16.0.1 : 8443
TLS version: 1.2
Cipher:      default
TLS tickets: off
Duration:    10

( All peers are active, start to gather statistics )
TLS hs in progress 562 [9842 h/s], TCP open conns 562 [145 hs in progress], Errors 0
TLS hs in progress 496 [10222 h/s], TCP open conns 496 [127 hs in progress], Errors 0
TLS hs in progress 529 [10067 h/s], TCP open conns 529 [163 hs in progress], Errors 0
TLS hs in progress 532 [10192 h/s], TCP open conns 532 [125 hs in progress], Errors 0
TLS hs in progress 460 [10120 h/s], TCP open conns 460 [133 hs in progress], Errors 0
TLS hs in progress 522 [10033 h/s], TCP open conns 522 [176 hs in progress], Errors 0
TLS hs in progress 498 [10143 h/s], TCP open conns 498 [161 hs in progress], Errors 0
TLS hs in progress 401 [9954 h/s], TCP open conns 402 [132 hs in progress], Errors 0
TLS hs in progress 529 [9888 h/s], TCP open conns 529 [134 hs in progress], Errors 0
TLS hs in progress 579 [9859 h/s], TCP open conns 579 [158 hs in progress], Errors 0
========================================
 TOTAL:           SECONDS 10; HANDSHAKES 100342
 HANDSHAKES/sec:  MAX 10222; AVG 10030; 95P 9842; MIN 9842
 LATENCY (ms):    MIN 15.595; AVG 51.8911; 95P 90.1826; MAX 173.215 

The following events occurred:
2024-06-19      12:02:51.987908 1718812971.987908: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:52.188361 1718812972.188361: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:52.388697 1718812972.388697: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 3. Retrying...
2024-06-19      12:02:52.589637 1718812972.589637: Overload warning: the minor watchdog timer 500ms has been tripped (704), 119 trips remaining.
2024-06-19      12:02:52.589770 1718812972.589770: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:52.790061 1718812972.790061: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:52.990833 1718812972.990833: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:53.191153 1718812973.191153: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:53.392045 1718812973.392045: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:53.592396 1718812973.592396: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:53.793248 1718812973.793248: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:53.993687 1718812973.993687: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:54.194642 1718812974.194642: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:54.394967 1718812974.394967: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:54.595730 1718812974.595730: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:54.796095 1718812974.796095: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:54.997048 1718812974.997048: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:54.997111 1718812974.997111: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:54.997139 1718812974.997139: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:54.997156 1718812974.997156: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:54.997172 1718812974.997172: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:54.997549 1718812974.997549: Overload warning: the minor watchdog timer 500ms has been tripped (2408), 118 trips remaining.
2024-06-19      12:02:54.997692 1718812974.997692: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:55.197992 1718812975.197992: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:55.398319 1718812975.398319: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 3. Retrying...
2024-06-19      12:02:55.599088 1718812975.599088: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:55.799432 1718812975.799432: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:56.000276 1718812976.000276: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_WRITE. Attempt 1. Retrying...
2024-06-19      12:02:56.200569 1718812976.200569: SSL_connect failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Attempt 2. Retrying...
2024-06-19      12:02:56.401346 1718812976.401346: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:56.401406 1718812976.401406: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...
2024-06-19      12:02:56.401436 1718812976.401436: Overload warning: the minor watchdog timer 500ms has been tripped (1404), 117 trips remaining.
2024-06-19      12:02:56.402015 1718812976.402015: SSL_read failed with error: SSL I/O function returned SSL_ERROR_WANT_READ. Retrying...```

@nttranbao
Copy link

Downgrading SIPp to 3.6.1, and no issue at all.

Something breaks on 3.7.x

@giannetc
Copy link

giannetc commented Oct 7, 2024

I have the same issue as @nttranbao, downgrading to SIPp 3.6.1 works.
My setup also SOMETIMES works with 3.7.2 and 3.7.3, mostly when the server is not loaded, so I suspect sipp 3.7.x is allowing less time to the SSL responses (I'm using client certificate)

@giannetc
Copy link

giannetc commented Oct 9, 2024

I fixed my issue by changing SIPP_SSL_MAX_RETRIES from 10 (2 seconds) to 150 (30 seconds), yet there's definitely some difference from 3.6.x

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@nttranbao @hamid-elaosta @Failxxx @NikolayShakin @giannetc @Ambal17