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.

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

TLS1.3 support #752

Open
eliot4321 opened this issue Sep 22, 2021 · 38 comments
Open

TLS1.3 support #752

eliot4321 opened this issue Sep 22, 2021 · 38 comments

Comments

@eliot4321
Copy link

Hi,

I'm running CoAP over TLS using openssl, I would like to know how I can force the use of TLS1.3, as there is no option for it or information in the documentation?

Thanks in advance

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

There currently is no option to configure this. In src/coap_openssl.c, change all 3 occurrences of TLS1_VERSION to TLS1_3_VERSION for the SSL_CTX_set_min_proto_version() calls and rebuild the libcoap library.

Note that DTLS1.3 is not fully available yet.

@eliot4321
Copy link
Author

thanks, @mrdeep1, I will try this out and get back to you!
Just one question regarding DTLS1.3, I assume the RFC will come soon, they have already approved the latest draft in IETF.
So do you mean that you have already an implementation based on the latest draft?

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

As the supprt becomes available in OpenSSL, GnuTLS, Mbed TLS and TinyDTLS libraries, there may need to be some minor changes to the src/coap_{openssl|gnutls|mbedtls|tinydtls}.c files to get it functioning correctly. It may just work 'as is'.

The intent is to get the correct support in place for DTLS1.3.

@eliot4321
Copy link
Author

thanks, @mrdeep1 , I didn't know that there is support for DTLS1.3 by OpenSSL. I was looking around and I didn't succeed to find it.
I have tried the suggested solution by you to run TLS1.3, but it didn't work in Wireshark it's shown TLSv1.0 and the script is not working the output is a Fatal error.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

It is the version in the CLientHello that matters, not the version in the Record Layer

Are you using PSK or PKI?

  • for PSK, if Identity Hint Callback is set (defined), as this is not supported in (D)TLS1.3, the libcoap code falls back to (D)TLS1.2 as in src/coap-openssl.c
    if (setup_data->validate_ih_call_back) {
      if (session->proto == COAP_PROTO_DTLS) {
        SSL_set_max_proto_version(ssl, DTLS1_2_VERSION);
      }
#if !COAP_DISABLE_TCP
      else {
        SSL_set_max_proto_version(ssl, TLS1_2_VERSION);
      }
#endif /* !COAP_DISABLE_TCP */
      coap_log(LOG_DEBUG,
        "CoAP Client restricted to (D)TLS1.2 with Identity Hint callback\n");
    }

It is this line in examples/coap-client.c that need to be converted to = NULL.

dtls_psk.validate_ih_call_back = verify_ih_callback;

@eliot4321
Copy link
Author

thanks, @mrdeep1, I just noticed I have OpenSSL 1.1.0 I guess there is no tls1.3 support I have to upgrade to the latest one, I will let you know once I'm done. In meantime, could you please elaborate on how I can use the DTLS1.3 with libcoap?

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

Yes, you need a minimum of opensssl 1.1.1 for TLS1.3.

Until DTLS1.3 is supported by the TLS libraries that libcoap uses, then DTLS1.3 is not available in libcoap as the TLS libraries will not understand the "supported_versions" extension value 0xfefc used to indicate DTLS1.3 support. So, the simple answer is that you cannot use DTLS1.3 at present.

@eliot4321
Copy link
Author

eliot4321 commented Sep 22, 2021

after doing the mentioned changes, I'm getting this error when I'm trying to run make
Making all in examples
make[2]: Entering directory '/home/../Documents/tls/libcoap/examples'
CC coap-client.o
CCLD coap-client-openssl
../.libs/libcoap-3-openssl.so: undefined reference to EVP_CIPHER_get_iv_length' ../.libs/libcoap-3-openssl.so: undefined reference to EVP_CIPHER_get_block_size'
../.libs/libcoap-3-openssl.so: undefined reference to EVP_CIPHER_get_mode' ../.libs/libcoap-3-openssl.so: undefined reference to EVP_MD_get_size'
collect2: error: ld returned 1 exit status
Makefile:555: recipe for target 'coap-client-openssl' failed
make[2]: *** [coap-client-openssl] Error 1
make[2]: Leaving directory '/home/../Documents/tls/libcoap/examples'
Makefile:1089: recipe for target 'all-recursive' failed
make[1]: *** [all-recursive] Error 1
make[1]: Leaving directory '/home/../Documents/tls/libcoap'
Makefile:622: recipe for target 'all' failed
make: *** [all] Error 2
``

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

I would say that it is likely you are compiling against openssl-1.1.1, but linking against openssl-1.1.0

What does ldd ../.libs/libcoap-3-openssl.so tell you for the libssl and libcrypto libraries?

@eliot4321
Copy link
Author

here you are :
linux-vdso.so.1 (0x00007fff6a5cd000)
libssl.so.1.1 => /usr/lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007fc01baab000)
libcrypto.so.1.1 => /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 (0x00007fc01b5e0000)
libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fc01b1ef000)
libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fc01afd0000)
libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fc01adcc000)
/lib64/ld-linux-x86-64.so.2 (0x00007fc01bf6f000)

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

So, I am therefore assuming that /usr/lib/x86_64-linux-gnu/libssl.so.1.1 and /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 have just been rebuilt for Openssl 1.1.1 (have datestamp of just now) - correct ?

What version of OpenSSL did you build against (1.1.1?) ?

@eliot4321
Copy link
Author

OpenSSL around : "yes" (found OpenSSL 1.1.1), what I found out after checking.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

So, did you build with OpenSSL 3.0 (just recently released) - which has a #define EVP_CIPHER_block_size EVP_CIPHER_get_block_size, whereas OpenSSL 1.1.1 has EVP_CIPHER_block_size() as a function (which src/coap_openssl.c calls).

@eliot4321
Copy link
Author

I have just installed openssl 3.0, and I made the build but it shown openssl 1.1.1. How I can force it to use only openssl 3.0?

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

PKG_CONFIG_PATH=<path to where the 3.0 openssl.pc file is> ./configure .....

See HOWTO.dual.openssl

@eliot4321
Copy link
Author

eliot4321 commented Sep 22, 2021

I have made some changes, now it's working perfectly. Thanks a lot @mrdeep1
Just one remark in wireshark it's still shown tls1.2, is it just wireshark filters?
Screenshot from 2021-09-22 17-14-57
!

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Sep 22, 2021

image

It is all down to the supported_versions extension being the definitive answer.

@eliot4321
Copy link
Author

Hi @mrdeep1 ,

I have a question regarding CoAP over TLSv1.3.
I'm trying to send multiple requests, but I noticed that for every request in the same session a TLS negotiation is happening, the normal behavior should be for one session one negotiation, I guess I'm missing something in the predefined options?

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 15, 2021

You need to be more explicit here and provide some debug log where this is happening.

You for instance, should only be calling coap_new_client_session_pki()/coap_new_client_session_psk2() once to set up the CoAP session, and then do multiple coap_send() on that session.

@eliot4321
Copy link
Author

Hi @mrdeep1 ,

Thanks for your reply!
What I'm trying to do is to send multiple coap messages within one TLS session, with a delay of 5 seconds between requests, I have tried to do what you proposed and also add the delay manually in the code but it didn't work, I have used the examples/coap-client.c to make the changes.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 17, 2021

I assume that you are also calling coap_io_process() between the coap_send() calls to handle the responses coming back from the server.

It would be good to see -v9 verbose logs from the client application -certainly for the first 10 seconds.

@eliot4321
Copy link
Author

Please find below the logs after sending 10 requests, I guess it's working now but I don't understand why it's skipping the delay between requests:
Nov 17 18:40:45.956 DEBG ***0.0.0.0:0 <-> 127.0.0.1:5684 TLS : new outgoing session
Nov 17 18:40:45.956 DEBG sending CoAP request:
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7dc70 initialized
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x5779: delayed
Nov 17 18:40:45.956 DEBG sending CoAP request:
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e010 initialized
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577a: delayed
Nov 17 18:40:45.956 DEBG sending CoAP request:
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e3b0 initialized
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577b: delayed
Nov 17 18:40:45.956 DEBG sending CoAP request:
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e750 initialized
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577c: delayed
Nov 17 18:40:45.956 DEBG sending CoAP request:
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7eaf0 initialized
Nov 17 18:40:45.956 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577d: delayed
Nov 17 18:40:45.957 DEBG sending CoAP request:
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7ef00 initialized
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577e: delayed
Nov 17 18:40:45.957 DEBG sending CoAP request:
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7f3a0 initialized
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x577f: delayed
Nov 17 18:40:45.957 DEBG sending CoAP request:
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7f7e0 initialized
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x5780: delayed
Nov 17 18:40:45.957 DEBG sending CoAP request:
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7fca0 initialized
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x5781: delayed
Nov 17 18:40:45.957 DEBG sending CoAP request:
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc80170 initialized
Nov 17 18:40:45.957 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x5782: delayed
Nov 17 18:40:45.957 DEBG timeout is set to 90 seconds
Nov 17 18:40:45.958 DEBG ***EVENT: 0x1001
Nov 17 18:40:45.958 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:before SSL initialization
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server hello
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read encrypted extensions
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate request
Nov 17 18:40:45.960 INFO 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : unable to get certificate CRL: overridden: 'localhost' depth=0
Nov 17 18:40:45.960 INFO CN '127.0.0.1' presented by server (CA)
Nov 17 18:40:45.960 INFO CN 'localhost' presented by server (Certificate)
Nov 17 18:40:45.960 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate
Nov 17 18:40:45.961 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read server certificate verify
Nov 17 18:40:45.961 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read finished
Nov 17 18:40:45.962 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write change cipher spec
Nov 17 18:40:45.962 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client certificate
Nov 17 18:40:45.967 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write certificate verify
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write finished
Nov 17 18:40:45.968 DEBG ***EVENT: 0x01de
Nov 17 18:40:45.968 DEBG ***127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : sending CSM
v:1 t:CON c:CSM i:0000 {} [ Max-Message-Size:8388864, Block-wise-Transfer: ]
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server session ticket
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server session ticket
Nov 17 18:40:45.968 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 7 bytes
v:1 t:CON c:CSM i:0000 {} [ Max-Message-Size:8388864, Block-wise-Transfer: ]
Nov 17 18:40:45.968 DEBG ***127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : session connected
Nov 17 18:40:45.968 DEBG ***EVENT: 0x2001
Nov 17 18:40:45.969 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x5779: transmitted after delay
v:1 t:CON c:GET i:5779 {01} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.969 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577a: transmitted after delay
v:1 t:CON c:GET i:577a {02} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.969 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577b: transmitted after delay
v:1 t:CON c:GET i:577b {03} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.969 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577c: transmitted after delay
v:1 t:CON c:GET i:577c {04} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.969 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577d: transmitted after delay
v:1 t:CON c:GET i:577d {05} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577e: transmitted after delay
v:1 t:CON c:GET i:577e {06} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x577f: transmitted after delay
v:1 t:CON c:GET i:577f {07} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x5780: transmitted after delay
v:1 t:CON c:GET i:5780 {08} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x5781: transmitted after delay
v:1 t:CON c:GET i:5781 {09} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : mid=0x5782: transmitted after delay
v:1 t:CON c:GET i:5782 {0a} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 18:40:45.970 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {01} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.970 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {02} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {03} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {04} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {05} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {06} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {07} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.971 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.971 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {08} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.972 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.972 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {09} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.972 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.972 DEBG * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {0a} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 18:40:45.972 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc80170 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7fca0 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7f7e0 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7f3a0 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7ef00 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7eaf0 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e750 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e3b0 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7e010 released
Nov 17 18:40:45.972 DEBG ** 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : lg_crcv 0x559d5bc7dc70 released
Nov 17 18:40:45.973 INFO * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL3 alert write:warning:close notify
Nov 17 18:40:45.973 INFO * 127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : SSL3 alert read:warning:close notify
Nov 17 18:40:45.973 DEBG ***EVENT: 0x0000
Nov 17 18:40:45.973 DEBG ***127.0.0.1:52152 <-> 127.0.0.1:5684 TLS : session closed

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 17, 2021

What this looks like to me in pseudo code terms

coap_new_client_session_pki()
for i in 1 to 10 {
  coap_send() next data
  increment expected response
}
while waiting for outstanding responses {
  coap_io_process() any outstanding i/o including TLS setup
}
exit

There is no evidence of your 5 second delay between coap_send().
I would be expecting the pseudo code to be looking something like

coap_new_client_session_pki()
for i in 1 to 10 {
  coap_send() next data
  increment expected response
  coap_io_process(COAP_IO_NO_WAIT)
  delay(5 seconds)
}
while waiting for outstanding responses {
  coap_io_process() any outstanding i/o including TLS setup
}
exit

or even better to handle the 20 or so TLS setup packet exchanges following the TCP connect completing (which also takes time and is not immediate)

coap_new_client_session_pki()
coap_send() first data
increment expected response

while waiting for outstanding responses or more sends to do {
  coap_io_process(500) wait for up to 0.5 sec
  if more sends and time in secs mod 5 equals 0 {
     coap_send() next data
     decrement more sends
  }
}
exit

@eliot4321
Copy link
Author

That's what's happening now: Nov 17 19:46:17.808 DEBG ***0.0.0.0:0 <-> 127.0.0.1:5684 TLS : new outgoing session
Nov 17 19:46:17.808 DEBG sending CoAP request:
Nov 17 19:46:17.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f8c70 initialized
Nov 17 19:46:17.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6206: delayed
Nov 17 19:46:18.808 DEBG sending CoAP request:
Nov 17 19:46:18.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9010 initialized
Nov 17 19:46:18.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6207: delayed
Nov 17 19:46:19.809 DEBG sending CoAP request:
Nov 17 19:46:19.809 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f93b0 initialized
Nov 17 19:46:19.809 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6208: delayed
Nov 17 19:46:20.809 DEBG sending CoAP request:
Nov 17 19:46:20.809 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9750 initialized
Nov 17 19:46:20.809 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6209: delayed
Nov 17 19:46:21.810 DEBG sending CoAP request:
Nov 17 19:46:21.810 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9af0 initialized
Nov 17 19:46:21.810 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620a: delayed
Nov 17 19:46:22.811 DEBG sending CoAP request:
Nov 17 19:46:22.811 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9f00 initialized
Nov 17 19:46:22.811 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620b: delayed
Nov 17 19:46:23.812 DEBG sending CoAP request:
Nov 17 19:46:23.812 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fa3a0 initialized
Nov 17 19:46:23.812 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620c: delayed
Nov 17 19:46:24.813 DEBG sending CoAP request:
Nov 17 19:46:24.813 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fa7e0 initialized
Nov 17 19:46:24.813 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620d: delayed
Nov 17 19:46:25.813 DEBG sending CoAP request:
Nov 17 19:46:25.813 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112faca0 initialized
Nov 17 19:46:25.813 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620e: delayed
Nov 17 19:46:26.814 DEBG sending CoAP request:
Nov 17 19:46:26.815 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fb170 initialized
Nov 17 19:46:26.815 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x620f: delayed
Nov 17 19:46:27.816 DEBG timeout is set to 90 seconds
Nov 17 19:46:27.816 DEBG ***EVENT: 0x1001
Nov 17 19:46:27.817 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:before SSL initialization
Nov 17 19:46:27.820 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 17 19:46:27.820 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 17 19:46:27.820 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server hello
Nov 17 19:46:27.820 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read encrypted extensions
Nov 17 19:46:27.820 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate request
Nov 17 19:46:27.820 INFO 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : unable to get certificate CRL: overridden: 'localhost' depth=0
Nov 17 19:46:27.820 INFO CN '127.0.0.1' presented by server (CA)
Nov 17 19:46:27.820 INFO CN 'localhost' presented by server (Certificate)
Nov 17 19:46:27.821 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate
Nov 17 19:46:27.821 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read server certificate verify
Nov 17 19:46:27.821 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read finished
Nov 17 19:46:27.821 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write change cipher spec
Nov 17 19:46:27.821 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client certificate
Nov 17 19:46:27.823 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write certificate verify
Nov 17 19:46:27.826 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write finished
Nov 17 19:46:27.826 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 19:46:27.826 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 19:46:27.826 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server session ticket
Nov 17 19:46:27.827 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 19:46:27.827 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSL negotiation finished successfully
Nov 17 19:46:27.827 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server session ticket
Nov 17 19:46:27.827 CIPH * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : Using cipher: TLS_AES_256_GCM_SHA384
Nov 17 19:46:27.827 DEBG ***EVENT: 0x01de
Nov 17 19:46:27.827 DEBG ***127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : sending CSM
v:1 t:CON c:CSM i:0000 {} [ Max-Message-Size:8388864, Block-wise-Transfer: ]
Nov 17 19:46:27.828 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 7 bytes
v:1 t:CON c:CSM i:0000 {} [ Max-Message-Size:8388864, Block-wise-Transfer: ]
Nov 17 19:46:27.828 DEBG ***127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : session connected
Nov 17 19:46:27.829 DEBG ***EVENT: 0x2001
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x6206: transmitted after delay
v:1 t:CON c:GET i:6206 {01} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x6207: transmitted after delay
v:1 t:CON c:GET i:6207 {02} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x6208: transmitted after delay
v:1 t:CON c:GET i:6208 {03} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x6209: transmitted after delay
v:1 t:CON c:GET i:6209 {04} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620a: transmitted after delay
v:1 t:CON c:GET i:620a {05} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620b: transmitted after delay
v:1 t:CON c:GET i:620b {06} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620c: transmitted after delay
v:1 t:CON c:GET i:620c {07} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620d: transmitted after delay
v:1 t:CON c:GET i:620d {08} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.829 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620e: transmitted after delay
v:1 t:CON c:GET i:620e {09} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.830 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : mid=0x620f: transmitted after delay
v:1 t:CON c:GET i:620f {0a} [ Uri-Path:.well-known, Uri-Path:core ]
Nov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {01} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {02} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {03} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {04} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {05} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {06} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {07} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {08} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.830 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {09} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.830 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.873 DEBG * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : received 161 bytes
v:1 t:CON c:2.05 i:0000 {0a} [ Content-Format:application/link-format, Size2:151 ] :: '</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obs'
Nov 17 19:46:27.874 DEBG ** process incoming 2.05 response:
</>;title="General Info";ct=0,;if="clock";rt="ticks";title="Internal Clock";ct=0;obs,;ct=0,</example_data>;title="Example Data";ct=0;obsNov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fb170 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112faca0 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fa7e0 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112fa3a0 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9f00 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9af0 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9750 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f93b0 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9010 released
Nov 17 19:46:27.874 DEBG ** 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f8c70 released
Nov 17 19:46:27.874 INFO * 127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : SSL3 alert write:warning:close notify
Nov 17 19:46:27.874 DEBG ***EVENT: 0x0000
Nov 17 19:46:27.874 DEBG ***127.0.0.1:54146 <-> 127.0.0.1:5684 TLS : session closed

@eliot4321
Copy link
Author

I don't understand why not the delay is applied after one request is complete(receiving the response from the coap server).

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 17, 2021

Without seeing the changes you have made to coap-client.c, it is not possible to say,

Nov 17 19:46:17.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6206: delayed
Nov 17 19:46:18.808 DEBG sending CoAP request:
Nov 17 19:46:18.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : lg_crcv 0x55d1112f9010 initialized
Nov 17 19:46:18.808 DEBG ** 0.0.0.0:0 <-> 127.0.0.1:5684 TLS : mid=0x6207: delayed

Indicates a 1 sec delay between each coap_send(). However it does not appear that you are calling coap_io_process() between the two coap_send() and so there is no mechanism to handle the TCP connected state and then to start the sending of the TLS handshakes.
For example,

Nov 17 19:46:27.816 DEBG timeout is set to 90 seconds   # Code is coap_log(LOG_DEBUG, "timeout is set to %u seconds\n", wait_seconds);
Nov 17 19:46:27.816 DEBG ***EVENT: 0x1001 # Event is TCP connected

is reported in the logs after you have done all the coap_send()s, and then all the TLS handshakes start.

@eliot4321
Copy link
Author

You are right, it seems creating a new coap request and send it it's in a different loop then coap_io_process(). I'm still efering to the coap-client.c file in examples folder.
I guess I need to create a customized coap function for my need, is how to include the TLS handshake their . Or it' easy to modify the same file?

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 17, 2021

libcoap handles all the necessary TLS setup work each time a call_io_process() is called. So, call_io_process() needs to be in the coap_send() loop. Yes, your local copy of examples/coap-client.c will need to get updated along the lines of the pseudo code that I referred to earlier.

@eliot4321
Copy link
Author

Thanks, I have followed your proposals and It's working now. One questions I have noticed a weird behavior in Wireshark it seems the client is sending two requests instead of one, and, the first request after the certificate exchange is quite big
Screenshot from 2021-11-18 10-07-24
.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 18, 2021

Reading the debug logs will tell you why both line 22 and 24 were sent immediately adter each other - my suspicion is that your code is sending out 2 of them at this point. Line 20 is a different length so is likelt to be a Coap CSM RFC8323.

Due to the nature of TCP, multiple writes can be sent in a single packet (and conversly a large write can span multiple packets) and so I woud say line 18 is likely to compise of the final part of the TLS exchange and the CSM from the server.

So apart from your potential bug re lines 22 and 24 this looks fine to me.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 18, 2021

I have created PR #773 to add in the necessary code for supporting seperation between the -G requests.

@eliot4321
Copy link
Author

Thanks a lot for your efforts!
I have tried your code but it seems it still having the same behavior with some additional requests. I'm sending 3 requests but you can see in Wireshark there is a record of more
Screenshot from 2021-11-18 17-08-23
.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 18, 2021

There is a certain point in the TLS handshake where all the information is encrypted and wireshark can only report it as application data as it has no idea as to the record type.

So, looking at the libcoap logs when I do a test, I get

Nov 18 15:42:13.285 DEBG ***EVENT: 0x1001
Nov 18 15:42:13.286 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:before SSL initialization
Nov 18 15:42:13.286 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 18 15:42:13.287 INFO ****** Next wakeup time 1271310.319000000
Nov 18 15:42:13.287 INFO ****** Next wakeup time 1271310.319000000
Nov 18 15:42:13.325 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client hello
Nov 18 15:42:13.325 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server hello
Nov 18 15:42:13.326 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read encrypted extensions
Nov 18 15:42:13.326 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate request
Nov 18 15:42:13.326 INFO    127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : unable to get certificate CRL: overridden: 'server.sample.example.com' depth=0
Nov 18 15:42:13.326 INFO CN 'ca.example.com' presented by server (CA)
Nov 18 15:42:13.327 INFO CN 'server.sample.example.com' presented by server (Certificate)
Nov 18 15:42:13.327 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read server certificate
Nov 18 15:42:13.327 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:TLSv1.3 read server certificate verify
Nov 18 15:42:13.328 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS read finished
Nov 18 15:42:13.328 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write change cipher spec
Nov 18 15:42:13.328 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client certificate
Nov 18 15:42:13.363 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write certificate verify
Nov 18 15:42:13.363 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write finished
Nov 18 15:42:13.363 CIPH *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : Using cipher: TLS_AES_256_GCM_SHA384
Nov 18 15:42:13.363 DEBG ***EVENT: 0x01de

Note in particular. matching change cipher spec, there continues

Nov 18 15:42:13.328 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write change cipher spec
Nov 18 15:42:13.328 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write client certificate
Nov 18 15:42:13.363 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write certificate verify
Nov 18 15:42:13.363 DEBG *  127.0.0.1:46870 <-> 127.0.0.1:5684 TLS : SSL_connect:SSLv3/TLS write finished

where there are 2 (seen as) application data (client certificate/client verify) being sent over the wire.

This looks fine to me.

@eliot4321
Copy link
Author

I understand, so I assume it will be hard the measure the RTT of the requests in case sending 20 request as it will hard to track each request. Or it could be done with the code but that require some changes in the library to record ACK time of the response from the server.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 18, 2021

The client sends a request, to which there is a response tracked by the unique to response/request token. If you want you can record the time between the token being used and when it is finished with.

libcoap neves sees the TCP ACK response.

@eliot4321
Copy link
Author

I assume those are not reported in the logs? Another question, can you point me to the API used to create a resource as I need to request specific JSON data for a specific URI?

Thanks a lot for your help!

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Nov 18, 2021

coap_resource(3). All the documentation you need should be available at Documentation

@eliot4321
Copy link
Author

Thanks! Which variable you have used to fix to one-second delay as I need to make it dynamic? I need to change it

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants