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

TinyDTLS select timeout #314

Closed
jitin17 opened this issue Mar 16, 2019 · 12 comments
Closed

TinyDTLS select timeout #314

jitin17 opened this issue Mar 16, 2019 · 12 comments

Comments

@jitin17
Copy link

jitin17 commented Mar 16, 2019 •
edited
Loading

While trying to establish a secure connection to coaps://californium.eclipse.org on ESP32 using TinyDTLS, I observe the connection to be stuck somewhere. I am attaching the log below:

Mar 16 11:24:45 DEBG ***0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: new outgoing session
Mar 16 11:24:45 DEBG ***new session 0x3ffbaa78
Mar 16 11:24:45 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 67 bytes
Mar 16 11:24:45 DEBG ** 0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: tid=58363: delayed
Mar 16 11:24:45 DEBG ** DTLS global timeout set to 2010ms
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: received 60 bytes
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 99 bytes
Mar 16 11:24:46 DEBG ** DTLS global timeout set to 1377ms
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: received 120 bytes
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 30 bytes
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 14 bytes
Mar 16 11:24:46 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 53 bytes
Mar 16 11:24:46 DEBG ** DTLS global timeout set to 1992ms
Mar 16 11:24:47 DEBG ** DTLS global timeout set to 992ms
Mar 16 11:24:48 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 30 bytes
Mar 16 11:24:48 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 14 bytes
Mar 16 11:24:48 DEBG ** DTLS global timeout set to 100ms
Mar 16 11:24:48 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 53 bytes
Mar 16 11:24:48 DEBG ** DTLS global timeout set to 4001ms
Mar 16 11:24:49 DEBG ** DTLS global timeout set to 3001ms
Mar 16 11:24:50 DEBG ** DTLS global timeout set to 2001ms
Mar 16 11:24:51 DEBG ** DTLS global timeout set to 1001ms
Mar 16 11:24:52 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 30 bytes
Mar 16 11:24:52 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 14 bytes
Mar 16 11:24:52 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 53 bytes
Mar 16 11:24:52 DEBG ** DTLS global timeout set to 8111ms
Mar 16 11:24:53 DEBG ** DTLS global timeout set to 7111ms
Mar 16 11:24:54 DEBG ** DTLS global timeout set to 6111ms
Mar 16 11:24:55 DEBG ** DTLS global timeout set to 5111ms
Mar 16 11:24:56 DEBG ** DTLS global timeout set to 4111ms
Mar 16 11:24:57 DEBG ** DTLS global timeout set to 3111ms
Mar 16 11:24:58 DEBG ** DTLS global timeout set to 2111ms
Mar 16 11:24:59 DEBG ** DTLS global timeout set to 1111ms
Mar 16 11:25:00 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 30 bytes
Mar 16 11:25:00 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 14 bytes
Mar 16 11:25:00 DEBG *  0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: sent 53 bytes
Mar 16 11:25:00 DEBG ** DTLS global timeout set to 16131ms
Mar 16 11:25:01 DEBG ** DTLS global timeout set to 15131ms
Mar 16 11:25:02 DEBG ** DTLS global timeout set to 14131ms
Mar 16 11:25:03 DEBG ** DTLS global timeout set to 13131ms
Mar 16 11:25:04 DEBG ** DTLS global timeout set to 12131ms
Mar 16 11:25:05 DEBG ** DTLS global timeout set to 11131ms
Mar 16 11:25:06 DEBG ** DTLS global timeout set to 10131ms
Mar 16 11:25:07 DEBG ** DTLS global timeout set to 9131ms
Mar 16 11:25:08 DEBG ** DTLS global timeout set to 8131ms
Mar 16 11:25:09 DEBG ** DTLS global timeout set to 7131ms
Mar 16 11:25:10 DEBG ** DTLS global timeout set to 6131ms
Mar 16 11:25:11 DEBG ** DTLS global timeout set to 5131ms
Mar 16 11:25:12 DEBG ** DTLS global timeout set to 4131ms
Mar 16 11:25:13 DEBG ** DTLS global timeout set to 3131ms
Mar 16 11:25:14 DEBG ** DTLS global timeout set to 2131ms
E (38595) CoAP_client: select timeout
Mar 16 11:25:15 WARN dtls_send_to_peer: cannot find local interface
Mar 16 11:25:15 DEBG ***removed session 0x3ffbaa78
Mar 16 11:25:15 DEBG ***0.0.0.0:49154 <-> 104.196.15.150:5684 DTLS: session closed

It is very likely that something is amiss on my side.
@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 16, 2019

Have you set up a PSK + IDENTITY definition? Not sure what coaps://californium.eclipse.org supports on that front.
tinydtls only supports PSK from within libcoap at this point., so cannot support any form of PKI exchanges.
You need to add / replace in the client code
session = coap_new_client_session( ctx, &bind_addr, dst, proto );
with
session = coap_new_client_session_psk( ctx, &bind_addr, dst, proto, identity, key, key_len );

I think that the 0.0.0.0 source address is down to the lack of RFC 3542 section 20 support.

@jitin17
Copy link
Author

jitin17 commented Mar 16, 2019 •
edited
Loading

I have had a difficult time finding some COAP(S) server. Do you know any standard coaps endpoint with support for generating PSK + identity?

You need to add / replace in the client code
session = coap_new_client_session( ctx, &bind_addr, dst, proto );
with
session = coap_new_client_session_psk( ctx, &bind_addr, dst, proto, identity, key, key_len );

I had replaced coap_new_client_session() with coap_new_client_session_psk(), and used PSK + Identity that I found at a random page(used in openssl command given below)

Somehow with the same PSK + identity, I am able to connect to coaps://californium.eclipse.org with openssl s_client

openssl s_client -debug -dtls1_2 -psk_identity password -psk 736573616D65 -connect californium.eclipse.org:5684

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 16, 2019

Looking at a pcap taken when doing the openssl s_client, it tells me that the session goes into PKI mode

image

Probably the best thing to do is to build the standalone version of libcoap, and then use its example server with whatever preshared key you want to test against.

$ git clone https://github.com/obgm/libcoap --recursive
$ cd libcoap
$ ./autogen.sh
$ ./configure --enable-dtls --with-tinydtls --disable-shared --disable-doxygen --disable-manpages
$ make
$ cd examples
$ ./coap-server -k 1234

Note that the PSK is in ascii for libcoap, but hexadecimal for s_client.

@jitin17
Copy link
Author

jitin17 commented Mar 18, 2019 •
edited
Loading

@mrdeep1 I did set up the local coap server, yet I am facing the same issue. I am attaching the server log:

Mar 18 13:02:54 DEBG *  [::]:5684 <-> [::ffff:192.168.43.241]:49153 (if26727664) DTLS: received 67 bytes
Mar 18 13:02:54 DEBG dtls_handle_message: PEER NOT FOUND
Mar 18 13:02:54 DEBG peer addr: [::ffff:192.168.43.241]:49153
Mar 18 13:02:54 DEBG got packet 22 (67 bytes)
Mar 18 13:02:54 DEBG receive header: (13 bytes):
00000000 16 FE FF 00 00 00 00 00  00 00 00 00 36
Mar 18 13:02:54 DEBG receive unencrypted: (54 bytes):
00000000 01 00 00 2A 00 00 00 00  00 00 00 2A FE FD 00 00
00000010 00 00 00 C7 29 99 E1 D0  45 53 D5 64 08 7B D0 39
00000020 35 8F E9 0B 81 28 8D CB  2C 53 4C 9F 2F 44 00 00
00000030 00 02 C0 A8 01 00
Mar 18 13:02:54 DEBG received handshake packet of type: client_hello (1)
Mar 18 13:02:54 DEBG handle handshake packet of type: client_hello (1)
Mar 18 13:02:54 DEBG create cookie: (16 bytes): B40F652BE3E104343E181470D7BC3649
Mar 18 13:02:54 DEBG compare with cookie: (0 bytes):
Mar 18 13:02:54 DEBG cookie len is 0!
Mar 18 13:02:54 DEBG send handshake packet of type: hello_verify_request (3)
Mar 18 13:02:54 DEBG send header: (13 bytes):
00000000 16 FE FF 00 00 00 00 00  00 00 00 00 1F
Mar 18 13:02:54 DEBG send unencrypted: (12 bytes):
00000000 03 00 00 13 00 00 00 00  00 00 00 13
Mar 18 13:02:54 DEBG send unencrypted: (19 bytes):
00000000 FE FD 10 B4 0F 65 2B E3  E1 04 34 3E 18 14 70 D7
00000010 BC 36 49
Mar 18 13:02:54 WARN dtls_send_to_peer: cannot find local interface
Mar 18 13:02:54 WARN cannot send HelloVerify request
Mar 18 13:02:54 WARN error in dtls_verify_peer err: -3
Mar 18 13:02:54 WARN error while handling handshake packet
Mar 18 13:02:57 DEBG *  [::]:5684 <-> [::ffff:192.168.43.241]:49153 (if26727664) DTLS: received 67 bytes
Mar 18 13:02:57 DEBG dtls_handle_message: PEER NOT FOUND
Mar 18 13:02:57 DEBG peer addr: [::ffff:192.168.43.241]:49153
Mar 18 13:02:57 DEBG got packet 22 (67 bytes)
Mar 18 13:02:57 DEBG receive header: (13 bytes):
00000000 16 FE FD 00 00 00 00 00  00 00 01 00 36
Mar 18 13:02:57 DEBG receive unencrypted: (54 bytes):
00000000 01 00 00 2A 00 00 00 00  00 00 00 2A FE FD 00 00
00000010 00 00 00 C7 29 99 E1 D0  45 53 D5 64 08 7B D0 39
00000020 35 8F E9 0B 81 28 8D CB  2C 53 4C 9F 2F 44 00 00
00000030 00 02 C0 A8 01 00
Mar 18 13:02:57 DEBG received handshake packet of type: client_hello (1)
Mar 18 13:02:57 DEBG handle handshake packet of type: client_hello (1)
Mar 18 13:02:57 DEBG create cookie: (16 bytes): B40F652BE3E104343E181470D7BC3649
Mar 18 13:02:57 DEBG compare with cookie: (0 bytes):
Mar 18 13:02:57 DEBG cookie len is 0!
Mar 18 13:02:57 DEBG send handshake packet of type: hello_verify_request (3)
Mar 18 13:02:57 DEBG send header: (13 bytes):
00000000 16 FE FF 00 00 00 00 00  00 00 00 00 1F
Mar 18 13:02:57 DEBG send unencrypted: (12 bytes):
00000000 03 00 00 13 00 00 00 00  00 00 00 13
Mar 18 13:02:57 DEBG send unencrypted: (19 bytes):
00000000 FE FD 10 B4 0F 65 2B E3  E1 04 34 3E 18 14 70 D7
00000010 BC 36 49
Mar 18 13:02:57 WARN dtls_send_to_peer: cannot find local interface
Mar 18 13:02:57 WARN cannot send HelloVerify request
Mar 18 13:02:57 WARN error in dtls_verify_peer err: -3
Mar 18 13:02:57 WARN error while handling handshake packet

It seems that the client is not receiving HelloVerifyRequest from the server.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 18, 2019

Mar 18 13:02:54 DEBG * [::]:5684 <-> [::ffff:192.168.43.241]:49153 (if26727664) DTLS: received 67 bytes

There are 2 things that I do not expect to see on this initial line
[::]:5684 and if26727664. On my Centos 7 system, I get
Mar 18 09:16:47 DEBG * [::ffff:192.168.0.63]:5684 <-> [::ffff:192.168.0.63]:53398 (if1) DTLS: received 67 bytes
and they both point to CMSG not being handled (code is looking for a cmsghdr that is the local interface for IPv6), so it looks like your build system does not properly support RFC 3542 section 20 which is a part of the recvmsg() function.
As if26727664 (looks like an uninitialized value for if) cannot be found, then the response packet from the coap-server is not getting transmitted.

As I had to put in a workaround for recvmsg() in the esp-idf code the coap_server (and possibly coap_client) there will have the same issue - so that needs to be worked on - I will look into that now.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 18, 2019

What type of system did you build the coap-server on?

@jitin17
Copy link
Author

jitin17 commented Mar 18, 2019

@mrdeep1 When I was running it on macOS high Sierra v10.13.4, there was some problem with decryption. And when I hosted the coap-server on Ububtu v18.04.1, ESP32 coap-client worked as expected. So, I think esp-idf's lwip not having RFC 3542 section 20 support won't be a blocker. I think we can close this issue.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 18, 2019

I have been doing some researching into this - and the interface index of 26727664 you reported in the log output (if26727664) is fine (but is it correct though?) within the libcoap context (as it is held as an int), but withing the tindydtls context it is held as a uint8_t - and so the message
Mar 18 13:02:54 WARN dtls_send_to_peer: cannot find local interface
was generated when effectively libcoap ifindex did not match tinydtls ifindex in the appropriate structures - and hence ongoing failure.
@obgm I guess that ifindex within tinydtls struct session_t should really be an int as interface indexes are not restricted to a max of 255.

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Mar 18, 2019

@jitin17 Good that the coap_client is now running. For the coap_server, you will need to add some extra code to set up a new endpoint of the form
ep_dtls = coap_new_endpoint(ctx, &addrs, COAP_PROTO_DTLS);
and define the PSK information to the ctx by
coap_context_set_psk(ctx, hint, key, key_length);

It would be good to see your ESP-IDF DTLS updates - so that I can sanity check things at some point.

@jitin17
Copy link
Author

jitin17 commented Mar 18, 2019

@mrdeep1 I am impressed by the patience and vigour you display while trying to solve problems and also your detail-rich answers.

It would be good to see your ESP-IDF DTLS updates - so that I can sanity check things at some point.

We need to find a clean way to handle issue addressed in #313 PR

@mrdeep1
Copy link
Collaborator

mrdeep1 commented Aug 31, 2019

@jitin17 Can this be closed off now as I believe that everything has been resolved?

@obgm
Copy link
Owner

obgm commented Sep 20, 2019

Closing as this seems to be solved.

@obgm obgm closed this as completed Sep 20, 2019
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
3 participants
@obgm @jitin17 @mrdeep1