feat: add ability to trace handshake #64

ainghazal · 2024-02-08T17:49:59Z

Checklist

I have read the contribution guidelines
Iff you changed code related to services, or inter-service communication, make sure you update the diagrams in ARCHITECTURE.md.
Reference issue for this pull request:

Description

In order to do that, we refactor the configuration handling. We move
options to openvpn options, and we create a config object that is
broader in scope.

In order to do that, we refactor the configuration handling. We move options to openvpn options, and we create a config object that is broader in scope. This commit also updates the binary entrypoint to test this functionality. Since I was here, I added the pinger too to exercise the pinger over the tunnel.

I'm reverting a recent "fix" that was inverting the local-remote session id check - the error in that commit was to change the check to match the description in the comment. In reality, it was the comment that was wrong. The reason why we cannot check remote session id in all packets is because remote-session-id only present if the packet has an ack array. The handshake was broken by the previous change, but I did not catch it because the integration tests were not running for the refactored codebase. Also, this commit enables integration tests for the new internal path to avoid this kind of errors in the future. Some test code was removed, because the script to parse certs etc was written before minivpn could parse inline credentials. not needed anymore.

ainghazal · 2024-02-09T16:53:25Z

I've changed the trace marshaling a bit, still playing with readability and redundancy. I think I'll start testing this on the wild.

Here's a dump of a valid handshake with the latest in this branch (generated with the binary in #66 )

Right at the beginning, it jumps to the eye that we're not properly initializing the negotiation state before sending the packet. @bassosimone let me know if there's some oddity that you see here:

[
  {
    "operation": "packet_out",
    "stage": "UNDEF",
    "t": 0.00018644,
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_HARD_RESET_CLIENT_V2",
      "id": 0,
      "acks": null,
      "payload_size": 0,
      "send_attempts": 1
    }
  },
  {
    "operation": "state",
    "stage": "PRE_START",
    "t": 0.00023592,
    "packet": null
  },
  {
    "operation": "state",
    "stage": "START",
    "t": 0.035379056,
    "packet": null
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.035393836,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_HARD_RESET_SERVER_V2",
      "id": 0,
      "acks": [
        0
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_out",
    "stage": "START",
    "t": 0.035894886,
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 1,
      "acks": [
        0
      ],
      "payload_size": 281,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.069690563,
    "packet": {
      "operation": "read",
      "opcode": "P_ACK_V1",
      "id": 0,
      "acks": [
        1
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.069853923,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 1,
      "acks": null,
      "payload_size": 1174,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.069863593,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 2,
      "acks": null,
      "payload_size": 284,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "SENT_KEY",
    "t": 0.071535524,
    "packet": null
  },
  {
    "operation": "packet_out",
    "stage": "SENT_KEY",
    "t": 0.071564284,
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 2,
      "acks": null,
      "payload_size": 1036,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_out",
    "stage": "SENT_KEY",
    "t": 0.071570554,
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 3,
      "acks": null,
      "payload_size": 296,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "SENT_KEY",
    "t": 0.10563023,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 3,
      "acks": [
        2
      ],
      "payload_size": 158,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "SENT_KEY",
    "t": 0.10601031,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 4,
      "acks": [
        3
      ],
      "payload_size": 200,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "GOT_KEY",
    "t": 0.10608311,
    "packet": null
  },
  {
    "operation": "packet_out",
    "stage": "GOT_KEY",
    "t": 0.10612168,
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 4,
      "acks": null,
      "payload_size": 35,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "GOT_KEY",
    "t": 0.139239737,
    "packet": {
      "operation": "read",
      "opcode": "P_ACK_V1",
      "id": 0,
      "acks": [
        4
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "GOT_KEY",
    "t": 0.139274967,
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 5,
      "acks": null,
      "payload_size": 291,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "ACTIVE",
    "t": 0.139348757,
    "packet": null
  },
  {
    "operation": "state",
    "stage": "GENERATED_KEYS",
    "t": 0.139443627,
    "packet": null
  }
]

should not return in the presence of malformed packets. we still need to properly log & trace these events, but this is a first defensive reaction to malformed input. - Related: ooni#67

ainghazal · 2024-02-11T19:46:34Z

@bassosimone removed all the overlapping changes from #65 and #66 - binary and integration tests can be tested together in the integration branch at https://github.com/ainghazal/minivpn/tree/handshake-trace-integration

ainghazal · 2024-02-11T19:48:46Z

for reference, here's an updated trace (after I changed the initial event timing and added tags as annotations; for client and server hello for now):

[
  {
    "operation": "state",
    "stage": "PRE_START",
    "t": 0.000493591,
    "tags": [],
    "packet": null
  },
  {
    "operation": "packet_out",
    "stage": "PRE_START",
    "t": 0.000507926,
    "tags": [],
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_HARD_RESET_CLIENT_V2",
      "id": 0,
      "acks": null,
      "payload_size": 0,
      "send_attempts": 1
    }
  },
  {
    "operation": "state",
    "stage": "START",
    "t": 0.048686083,
    "tags": [],
    "packet": null
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.04870451,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_HARD_RESET_SERVER_V2",
      "id": 0,
      "acks": [
        0
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_out",
    "stage": "START",
    "t": 0.049519546,
    "tags": [
      "client_hello"
    ],
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 1,
      "acks": [
        0
      ],
      "payload_size": 281,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.09883628,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_ACK_V1",
      "id": 0,
      "acks": [
        1
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.099096479,
    "tags": [
      "server_hello"
    ],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 1,
      "acks": null,
      "payload_size": 1174,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.09935176,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 2,
      "acks": null,
      "payload_size": 1174,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "START",
    "t": 0.099410356,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 3,
      "acks": null,
      "payload_size": 36,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "SENT_KEY",
    "t": 0.108286602,
    "tags": [],
    "packet": null
  },
  {
    "operation": "packet_out",
    "stage": "SENT_KEY",
    "t": 0.108444487,
    "tags": [],
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 2,
      "acks": null,
      "payload_size": 1284,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_out",
    "stage": "SENT_KEY",
    "t": 0.108468284,
    "tags": [],
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 3,
      "acks": null,
      "payload_size": 296,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "SENT_KEY",
    "t": 0.155445966,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 4,
      "acks": [
        2
      ],
      "payload_size": 158,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "SENT_KEY",
    "t": 0.157441445,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 5,
      "acks": [
        3
      ],
      "payload_size": 228,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "GOT_KEY",
    "t": 0.157713868,
    "tags": [],
    "packet": null
  },
  {
    "operation": "packet_out",
    "stage": "GOT_KEY",
    "t": 0.157897133,
    "tags": [],
    "packet": {
      "operation": "write",
      "opcode": "P_CONTROL_V1",
      "id": 4,
      "acks": null,
      "payload_size": 35,
      "send_attempts": 1
    }
  },
  {
    "operation": "packet_in",
    "stage": "GOT_KEY",
    "t": 0.205236791,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_ACK_V1",
      "id": 0,
      "acks": [
        4
      ],
      "payload_size": 0,
      "send_attempts": null
    }
  },
  {
    "operation": "packet_in",
    "stage": "GOT_KEY",
    "t": 0.205351335,
    "tags": [],
    "packet": {
      "operation": "read",
      "opcode": "P_CONTROL_V1",
      "id": 6,
      "acks": null,
      "payload_size": 221,
      "send_attempts": null
    }
  },
  {
    "operation": "state",
    "stage": "ACTIVE",
    "t": 0.205685896,
    "tags": [],
    "packet": null
  },
  {
    "operation": "state",
    "stage": "GENERATED_KEYS",
    "t": 0.205989473,
    "tags": [],
    "packet": null
  }
]

internal/model/config.go

bassosimone

Let's discuss my comments! Thank you!

internal/model/config.go

bassosimone · 2024-02-13T08:09:06Z

internal/model/config.go

+	IPAddr   string
+	AddrPort string


These two fields are a bit obscure to me? One of them is the address and the other the endpoint? Maybe call the second one endpoint? Maybe document each field? None of them is super obvious to me. What is protocol? "tcp" or "udp"?

one is only the ip address, the other (endpoint) includes the port. proto is either tcp or udp, correct. I'm going to add comments to those.

added documentation

internal/model/trace.go

bassosimone · 2024-02-13T08:12:49Z

internal/model/trace.go

+func (d Direction) String() string {
+	switch d {
+	case DirectionIncoming:
+		return "recv"


I think it would be more clear if DirectionIncoming mapped to "incoming", but maybe there is a reason by which you are using "recv" here that I am missing?

incoming and outgoing is more clear here indeed. I was thinking about what would be serialized in the trace. first I thought receive/send, and later read/write.

beyond any choice, I think the important problem is where the serialization happens. Probably we can just document the integer and let any user-facing string be the responsibility of the tracer.

internal/model/trace.go

bassosimone · 2024-02-13T09:15:12Z

pkg/tracex/trace.go

+
+	stg := session.SessionNegotiationState(stage)
+	e := newEvent(handshakeEventPacketIn, stg, t.TimeNow(), t.zeroTime)
+	e.LoggedPacket = logPacket(packet, -1, model.DirectionIncoming)


I am not super fond of using -1 here. Would it be possible to import and use the proper definitions?

Not using the proper definitions would make it more difficult for consumers, especially if we change the defines. I know it's not likely we'll change them, but I am playing a bit of a what-if+robustness game here.

fixed, moved the creation of optional.Value to the caller

pkg/tracex/trace.go

bassosimone · 2024-02-13T09:17:07Z

pkg/tracex/trace.go

+		Retries:     lp.Retries,
+	}
+	return json.Marshal(j)
+}


Same comment as above: we don't need a custom marshaler, just proper json:"xx" annotations.

the real problem here, to me, is to switch between internal types (like direction) and their string representation. is there any way to force string serialization from the json tag in a more elegant way?

nvm, forced the types to string and moved the json tags to the struct

pkg/tracex/trace.go

Co-authored-by: Simone Basso <[email protected]>

ainghazal · 2024-02-13T12:30:40Z

ok, I have changed the tracer interface to emit NegotiationsState instead of ints. I had to move the definitions to model to avoid a circular import. one thing I dislike is that there's too much stuff in model - at some point I'd consider putting some useful things (like state) in an importable path like pkg/state, but deferring on that for now.

bassosimone · 2024-02-13T12:54:46Z

ok, I have changed the tracer interface to emit NegotiationsState instead of ints. I had to move the definitions to model to avoid a circular import. one thing I dislike is that there's too much stuff in model - at some point I'd consider putting some useful things (like state) in an importable path like pkg/state, but deferring on that for now.

Agreed, it's important to note pain points because they're informative on how we can evolve the code.

ainghazal force-pushed the feat/handshake-trace branch from f96cb12 to d4ef98b Compare February 8, 2024 17:50

ainghazal requested a review from bassosimone February 8, 2024 17:50

ainghazal self-assigned this Feb 8, 2024

remove binary

d4ef98b

ainghazal mentioned this pull request Feb 8, 2024

feat: replace minivpn binary #66

Merged

3 tasks

ainghazal added 4 commits February 8, 2024 20:11

comments after review

4a2404a

tests: update tests after config refactor

9b96d65

add documentation to package

420c9f8

typo

4a06e7e

ainghazal mentioned this pull request Feb 9, 2024

tests: adapt integration tests to run against the refactored code #65

Merged

ainghazal added 5 commits February 9, 2024 15:26

make tracer public

e8eaeaf

iterate on tracer

6bd3583

x

79c9cf0

trace outgoing hard reset too

b2fcbfd

ainghazal added 10 commits February 10, 2024 17:46

change state before sending hard reset packet

8e6e391

annotate tls client hello & server hello

c36b7f1

bug: continue if received malformed input

5ac4cde

should not return in the presence of malformed packets. we still need to properly log & trace these events, but this is a first defensive reaction to malformed input. - Related: ooni#67

remove todo

fef4a84

remove on handshake done from interface

93331de

revert binary to main

3233f5a

remove binary from this branch

9e245c9

revert changes to pinger

39a9c9a

revert integration tests, they are on their own pr

882725b

delete main.go

866cdb4

document public methods

90e333a

linter

a3dba34

bassosimone reviewed Feb 13, 2024

View reviewed changes

internal/model/config.go Outdated Show resolved Hide resolved

bassosimone reviewed Feb 13, 2024

View reviewed changes

ainghazal and others added 16 commits February 13, 2024 11:23

Update internal/model/config.go

b37696b

Co-authored-by: Simone Basso <[email protected]>

Update internal/model/config.go

d7a931b

Co-authored-by: Simone Basso <[email protected]>

Update internal/model/trace.go

a149648

Co-authored-by: Simone Basso <[email protected]>

document remote fields

dd3d3e8

fix direction serialization

c05ba96

remove marshaling, cast fields into strings

514adf2

grammar

46fb370

minor fixes

66762e0

Update internal/optional/optional.go

07bcd61

Co-authored-by: Simone Basso <[email protected]>

Update internal/packetmuxer/service.go

dc5b90d

Co-authored-by: Simone Basso <[email protected]>

Update internal/packetmuxer/service.go

06b7488

Co-authored-by: Simone Basso <[email protected]>

Update internal/reliabletransport/receiver.go

c4fc44a

Co-authored-by: Simone Basso <[email protected]>

Update pkg/tracex/trace.go

23539c7

Co-authored-by: Simone Basso <[email protected]>

minor fixes

e9c54b3

move comment out of the struct

5c1f86a

move session negotiation states to model to avoid circular import

b16e276

ainghazal merged commit aa16602 into ooni:main Feb 13, 2024
8 checks passed

ainghazal deleted the feat/handshake-trace branch February 13, 2024 16:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add ability to trace handshake #64

feat: add ability to trace handshake #64

ainghazal commented Feb 8, 2024 •

edited

Loading

ainghazal commented Feb 9, 2024 •

edited

Loading

ainghazal commented Feb 11, 2024

ainghazal commented Feb 11, 2024

bassosimone left a comment

bassosimone Feb 13, 2024

ainghazal Feb 13, 2024

ainghazal Feb 13, 2024

bassosimone Feb 13, 2024

ainghazal Feb 13, 2024

bassosimone Feb 13, 2024

ainghazal Feb 13, 2024

bassosimone Feb 13, 2024

ainghazal Feb 13, 2024

ainghazal Feb 13, 2024

ainghazal commented Feb 13, 2024

bassosimone commented Feb 13, 2024

feat: add ability to trace handshake #64

feat: add ability to trace handshake #64

Conversation

ainghazal commented Feb 8, 2024 • edited Loading

Checklist

Description

ainghazal commented Feb 9, 2024 • edited Loading

ainghazal commented Feb 11, 2024

ainghazal commented Feb 11, 2024

bassosimone left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ainghazal commented Feb 13, 2024

bassosimone commented Feb 13, 2024

ainghazal commented Feb 8, 2024 •

edited

Loading

ainghazal commented Feb 9, 2024 •

edited

Loading