search

ooni / minivpn

A minimalistic OpenVPN implementation in Go
GNU General Public License v3.0
36 stars 6 forks source link

feat: add ability to trace handshake #64

Closed ainghazal closed 5 months ago

ainghazal commented 5 months ago

Checklist

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.

ainghazal commented 5 months ago

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
  }
]
ainghazal commented 5 months ago

@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 commented 5 months ago

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
  }
]
ainghazal commented 5 months ago

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 commented 5 months ago

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.