Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    OpenVPN server broken after upgrade

    OpenVPN
    2
    3
    1.5k
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • S
      Squeakie
      last edited by

      Hi,

      I upgraded my PfSense box from 2.4.1 to 2.5.2 and after the upgrade none of my VPN clients can connect to the OpenVPN server.

      When I checked the log file on one of the VPN clients I saw this:

      2021-12-09 11:59:41.143463 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:60928
2021-12-09 11:59:41.163663 MANAGEMENT: CMD 'pid'
2021-12-09 11:59:41.163811 MANAGEMENT: CMD 'auth-retry interact'
2021-12-09 11:59:41.163838 MANAGEMENT: CMD 'state on'
2021-12-09 11:59:41.163861 MANAGEMENT: CMD 'state'
2021-12-09 11:59:41.163893 MANAGEMENT: CMD 'bytecount 1'
2021-12-09 11:59:41.164910 *Tunnelblick: Established communication with OpenVPN
2021-12-09 11:59:41.168027 *Tunnelblick: >INFO:OpenVPN Management Interface Version 3 -- type 'help' for more info
2021-12-09 11:59:41.169449 MANAGEMENT: CMD 'hold release'
2021-12-09 11:59:45.556622 MANAGEMENT: CMD 'username "Auth" "Mac"'
2021-12-09 11:59:45.556757 MANAGEMENT: CMD 'password [...]'
2021-12-09 11:59:45.556934 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2021-12-09 11:59:45.563524 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-12-09 11:59:45.563574 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-12-09 11:59:45.563722 TCP/UDP: Preserving recently used remote address: [AF_INET]98.128.243.27:1194
2021-12-09 11:59:45.563850 Socket Buffers: R=[131072->131072] S=[131072->131072]
2021-12-09 11:59:45.563876 Attempting to establish TCP connection with [AF_INET]98.128.243.27:1194 [nonblock]
2021-12-09 11:59:45.563900 MANAGEMENT: >STATE:1639047585,TCP_CONNECT,,,,,,
2021-12-09 11:59:45.598957 TCP connection established with [AF_INET]98.128.243.27:1194
2021-12-09 11:59:45.599112 TCP_CLIENT link local: (not bound)
2021-12-09 11:59:45.599146 TCP_CLIENT link remote: [AF_INET]98.128.243.27:1194
2021-12-09 11:59:45.599208 MANAGEMENT: >STATE:1639047585,WAIT,,,,,,
2021-12-09 11:59:45.609863 MANAGEMENT: >STATE:1639047585,AUTH,,,,,,
2021-12-09 11:59:45.609942 TLS: Initial packet from [AF_INET]98.128.243.27:1194, sid=853fc067 21b3cff4
2021-12-09 11:59:45.637343 VERIFY OK: depth=1, CN=squeakie.se-ca, C=SE, ST=Stockholm, L=Stockholm, O=Lokal data, OU=Datacorner
2021-12-09 11:59:45.637744 VERIFY KU OK
2021-12-09 11:59:45.637769 Validating certificate extended key usage
2021-12-09 11:59:45.637782 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2021-12-09 11:59:45.637794 VERIFY EKU OK
2021-12-09 11:59:45.637958 VERIFY X509NAME OK: CN=Mac.squeakie.se, C=SE, ST=Stockholm, L=Stockholm, O=Lokal data, OU=Datacorner
2021-12-09 11:59:45.637972 VERIFY OK: depth=0, CN=Mac.squeakie.se, C=SE, ST=Stockholm, L=Stockholm, O=Lokal data, OU=Datacorner
2021-12-09 11:59:46.562557 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2021-12-09 11:59:46.562729 [Mac.squeakie.se] Peer Connection Initiated with [AF_INET]98.128.243.27:1194
2021-12-09 11:59:47.865711 MANAGEMENT: >STATE:1639047587,GET_CONFIG,,,,,,
2021-12-09 11:59:47.865908 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 11:59:52.460611 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 11:59:58.108102 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:03.295500 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:08.628422 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:13.079062 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:18.540558 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:23.816163 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:28.965092 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:33.181663 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:38.286436 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:43.376532 SENT CONTROL [Mac.squeakie.se]: 'PUSH_REQUEST' (status=1)
2021-12-09 12:00:48.403878 No reply from server after sending 12 push requests
2021-12-09 12:00:48.404500 SIGUSR1[soft,no-push-reply] received, process restarting

      And the VPN keeps on retrying.

      When I checked the logfile in PfSense I got this log.

      Dec 9 12:18:47	openvpn	40531	Mac/192.168.0.73:58337 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_45b607f72e113ea83b0c5cf4f8c74c0b.tmp
Dec 9 12:18:47	openvpn	40531	Mac/192.168.0.73:58337 TEST FILE '/tmp/openvpn_cc_45b607f72e113ea83b0c5cf4f8c74c0b.tmp' [1]
Dec 9 12:18:47	openvpn	40531	Mac/192.168.0.73:58337 TEST FILE '/var/etc/openvpn/server1/csc/DEFAULT' [0]
Dec 9 12:18:47	openvpn	40531	Mac/192.168.0.73:58337 TEST FILE '/var/etc/openvpn/server1/csc/Mac' [0]
Dec 9 12:18:47	openvpn	40531	Mac/192.168.0.73:58337 MULTI_sva: pool returned IPv4=192.168.2.2, IPv6=(Not enabled)
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: timeout set to 3274
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send_timeout 604800 [6]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=0 current=0 : [6]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=1 ks=S_ACTIVE lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=0 current=0 : [6]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 [Mac] Peer Connection Initiated with [AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STATE S_ACTIVE
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK received for pid 5, deleting from send buffer
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: received control channel packet s#=0 sid=21b174f0 52483d07
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 PID_TEST [0] [TLS_WRAP-0] [01111111111] 1639048716:11 1639048716:12 t=1639048727[0] r=[-1,64,15,0,1] sl=[53,11,64,528]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 DECRYPT FROM: 5f0f8b43 ae2cc4a7 997cb091 15e8029d 66081070 8efbc1f0 25f5f536 b76d535[more...]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: found match, session[0], sid=21b174f0 52483d07
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, rec-sid=21b174f0 52483d07, rec-ip=[AF_INET6]::ffff:192.168.0.73:58337, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: control channel, op=P_ACK_V1, IP=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:192.168.0.73:58337: P_ACK_V1 kid=0 sid=21b174f0 52483d07 tls_hmac=5f0f8b43 ae2cc4a7 997cb091 15e8029d 66081070 8efbc1f0 25f5f536 b76d535e pid=[ #12 / time = (1639048716) 2021-12-09 12:18:36 ] [ 5 sid=3fbd343c 7a125e9c ]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER read returned 62
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: RESET
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: GET FINAL len=62
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: ADD returned TRUE, buf_len=62, residual_len=0
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: ADD length_added=64
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: GET NEXT len=1626
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_READ mi=0x801224000
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_action a=TA_SOCKET_READ p=0
Dec 9 12:18:47	openvpn	40531	PO_WAIT[4,0] fd=10 rev=0x00000001 rwflags=0x0001 arg=0x801224000 [scalable]
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=8 arg=0x00000005
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_UNDEF
Dec 9 12:18:47	openvpn	40531	STREAM: SET NEXT, buf=[532,0] next=[532,1626] len=-1 maxlen=1626
Dec 9 12:18:47	openvpn	40531	STREAM: SET NEXT, buf=[532,0] next=[532,1626] len=-1 maxlen=1626
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: timeout set to 2
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send_timeout 2 [6] 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=1 current=0 : [6] 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK received for pid 4, deleting from send buffer
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: received control channel packet s#=0 sid=21b174f0 52483d07
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 PID_TEST [0] [TLS_WRAP-0] [1111111111] 1639048716:10 1639048716:11 t=1639048727[0] r=[-1,64,15,0,1] sl=[54,10,64,528]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 DECRYPT FROM: 04ea35b0 7e3ec2d2 06318fea a86408a5 3fe5ec4b 0cdc78d6 30e6393c e59b5a1[more...]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: found match, session[0], sid=21b174f0 52483d07
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, rec-sid=21b174f0 52483d07, rec-ip=[AF_INET6]::ffff:192.168.0.73:58337, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: control channel, op=P_ACK_V1, IP=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:192.168.0.73:58337: P_ACK_V1 kid=0 sid=21b174f0 52483d07 tls_hmac=04ea35b0 7e3ec2d2 06318fea a86408a5 3fe5ec4b 0cdc78d6 30e6393c e59b5a19 pid=[ #11 / time = (1639048716) 2021-12-09 12:18:36 ] [ 4 sid=3fbd343c 7a125e9c ]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER read returned 62
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: RESET
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: GET FINAL len=62
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: ADD returned TRUE, buf_len=62, residual_len=0
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: ADD length_added=64
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: GET NEXT len=1626
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_READ mi=0x801224000
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_action a=TA_SOCKET_READ p=0
Dec 9 12:18:47	openvpn	40531	PO_WAIT[4,0] fd=10 rev=0x00000001 rwflags=0x0001 arg=0x801224000 [scalable]
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=8 arg=0x00000005
Dec 9 12:18:47	openvpn	40531	MULTI: modified fd 4, mask 32768
Dec 9 12:18:47	openvpn	40531	TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	TLS: tls_process: timeout set to 2
Dec 9 12:18:47	openvpn	40531	ACK reliable_send_timeout 2 [6] 4 5
Dec 9 12:18:47	openvpn	40531	ACK reliable_can_send active=2 current=0 : [6] 4 5
Dec 9 12:18:47	openvpn	40531	TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	MULTI: modified fd 4, mask 8
Dec 9 12:18:47	openvpn	40531	MULTI: REAP range 224 -> 240
Dec 9 12:18:47	openvpn	40531	PO_WAIT[3,0] fd=8 rev=0x00000001 rwflags=0x0001 arg=0x00000005 [scalable]
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=8 arg=0x00000005
Dec 9 12:18:47	openvpn	40531	SCHEDULE: schedule_find_least wakeup=[2021-12-09 12:18:48 us=498334] pri=1017230411
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_post TA_SOCKET_WRITE -> TA_UNDEF
Dec 9 12:18:47	openvpn	40531	STREAM: SET NEXT, buf=[532,0] next=[532,1626] len=-1 maxlen=1626
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: timeout set to 2
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send_timeout 2 [6] 4 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=2 current=0 : [6] 4 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=3fbd343c 7a125e9c, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER write returned 302
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: WRITE 300 offset=30
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER WRITE [300] to [AF_INET6]::ffff:192.168.0.73:58337: P_CONTROL_V1 kid=0 sid=3fbd343c 7a125e9c tls_hmac=f36aa974 ba4c0e15 6c14477e 4ec8bc03 39f21c03 75b9df4c 774cf827 48fcde8c pid=[ #10 / time = (1639048726) 2021-12-09 12:18:46 ] [ ] pid=5 DATA 17030300 f138dd21 bfa48889 63074845 ec4d51ae 650c6e0a 9b59f443 0
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_WRITE mi=0x801224000
Dec 9 12:18:47	openvpn	40531	I/O WAIT status=0x0102
Dec 9 12:18:47	openvpn	40531	event_wait returned 2
Dec 9 12:18:47	openvpn	40531	PO_WAIT[3,1] fd=0 rev=0x00000001 rwflags=0x0001 arg=0x002b652c
Dec 9 12:18:47	openvpn	40531	PO_WAIT[0,0] fd=10 rev=0x00000004 rwflags=0x0002 arg=0x002b7228
Dec 9 12:18:47	openvpn	40531	I/O WAIT TR|Tw|Sr|SW [0/0]
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=0 arg=0x002b652c
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=4 arg=0x002b6528
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=5 arg=0x002b6524
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0002 ev=10 arg=0x002b7228
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_wait_lite a=TA_SOCKET_WRITE mi=0x801224000
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_action a=TA_SOCKET_WRITE p=1
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_post TA_SOCKET_WRITE -> TA_SOCKET_WRITE
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 SCHEDULE: schedule_add_modify wakeup=[2021-12-09 12:18:48 us=498334] pri=647888486
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: timeout set to 2
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send_timeout 2 [6] 4 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Reliable -> TCP/UDP
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ENCRYPT TO: f36aa974 ba4c0e15 6c14477e 4ec8bc03 39f21c03 75b9df4c 774cf827 48fcde8[more...]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ENCRYPT HMAC: f36aa974 ba4c0e15 6c14477e 4ec8bc03 39f21c03 75b9df4c 774cf827 48fcde8c
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 write_control_auth(): P_CONTROL_V1
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send ID 5 (size=250 to=2)
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=2 current=1 : [6] 4 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=1 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Outgoing Ciphertext -> Reliable
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK mark active outgoing ID 5
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 BIO read tls_read_ciphertext 246 bytes
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Outgoing Plaintext -> TLS
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 BIO write tls_write_plaintext 224 bytes
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STATE S_SENT_KEY
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=1 current=0 : [5] 4
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=0 ks=S_GOT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=0 state=S_GOT_KEY, mysid=3fbd343c 7a125e9c, stored-sid=21b174f0 52483d07, stored-ip=[AF_INET6]::ffff:192.168.0.73:58337
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TIMER: coarse timer wakeup 1 seconds
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER write returned 226
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STREAM: WRITE 224 offset=18
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TCPv6_SERVER WRITE [224] to [AF_INET6]::ffff:192.168.0.73:58337: P_CONTROL_V1 kid=0 sid=3fbd343c 7a125e9c tls_hmac=4e0b9166 462e18bb af5da54b ab76699b 65eadf93 5b1a1b94 8b4ec393 7baa584f pid=[ #9 / time = (1639048726) 2021-12-09 12:18:46 ] [ 4 sid=21b174f0 52483d07 ] pid=4 DATA 17030300 4a1357bb 952f2505 a4ae3cae f842c
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_WRITE mi=0x801224000
Dec 9 12:18:47	openvpn	40531	I/O WAIT status=0x0102
Dec 9 12:18:47	openvpn	40531	event_wait returned 2
Dec 9 12:18:47	openvpn	40531	PO_WAIT[3,1] fd=0 rev=0x00000001 rwflags=0x0001 arg=0x002b652c
Dec 9 12:18:47	openvpn	40531	PO_WAIT[0,0] fd=10 rev=0x00000004 rwflags=0x0002 arg=0x002b7228
Dec 9 12:18:47	openvpn	40531	I/O WAIT TR|Tw|Sr|SW [0/0]
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=0 arg=0x002b652c
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=4 arg=0x002b6528
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0001 ev=5 arg=0x002b6524
Dec 9 12:18:47	openvpn	98829	user 'Mac' authenticated
Dec 9 12:18:47	openvpn	40531	PO_CTL rwflags=0x0002 ev=10 arg=0x002b7228
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_wait_lite a=TA_SOCKET_WRITE mi=0x801224000
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_action a=TA_SOCKET_WRITE p=1
Dec 9 12:18:47	openvpn	40531	MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_SOCKET_WRITE
Dec 9 12:18:47	openvpn	40531	STREAM: SET NEXT, buf=[532,0] next=[532,1626] len=-1 maxlen=1626
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 SCHEDULE: schedule_add_modify wakeup=[2021-12-09 12:18:48 us=306882] pri=1477093179
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=86b45de1 448c6004, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: timeout set to 1
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send_timeout 2 [5] 4
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Reliable -> TCP/UDP
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ENCRYPT TO: 4e0b9166 462e18bb af5da54b ab76699b 65eadf93 5b1a1b94 8b4ec393 7baa584[more...]
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ENCRYPT HMAC: 4e0b9166 462e18bb af5da54b ab76699b 65eadf93 5b1a1b94 8b4ec393 7baa584f
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 write_control_auth(): P_CONTROL_V1
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK write ID 4 (ack->len=1, n=1)
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_send ID 4 (size=162 to=2)
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK reliable_can_send active=1 current=1 : [5] 4
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 TLS: tls_process: chg=1 ks=S_GOT_KEY lame=S_UNDEF to_link->len=0 wakeup=0
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 Outgoing Ciphertext -> Reliable
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 ACK mark active outgoing ID 4
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 BIO read tls_read_ciphertext 158 bytes
Dec 9 12:18:47	openvpn	40531	192.168.0.73:58337 STATE S_GOT_KEY

      I can´t see any obvious issues or errors.

      The VPN client are using Tunnelblick 3.8.7a (build 5770)

      Any takes?

      GertjanG 1 Reply Last reply Reply Quote 0
      • GertjanG
        Gertjan @Squeakie
        last edited by

        @squeakie

        pfSense 2.5.2 uses a new version of OpenVPN - see the pfSense release notes.
        This might, depending settings used, have an impact on the server client traffic.
        Did you exported clients settings ?
        Check also if "Tunnelblick 3.8.7a (build 5770)" supports the OpenVPN version that is used by pfSEnse :

        [2.5.2-RELEASE][root@pfsense.athome.net]/root: openvpn --version
OpenVPN 2.5.2 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Jun 24 2021
library versions: OpenSSL 1.1.1k-freebsd  25 Mar 2021, LZO 2.10

        The Openvpn version is 2.5.2, identical to the pfSense CE version, that's just a coincidence.
        OpenVPN 2.5.x had a lot of changes compared to 2.4.x (see OpenVPN 2.5.x release notes).

        No "help me" PM's please. Use the forum, the community will thank you.
        Edit : and where are the logs ??

        S 1 Reply Last reply Reply Quote 1
        • S
          Squeakie @Gertjan
          last edited by

          @gertjan said in OpenVPN server broken after upgrade:

          @squeakie

          pfSense 2.5.2 uses a new version of OpenVPN - see the pfSense release notes.
          This might, depending settings used, have an impact on the server client traffic.
          Did you exported clients settings ?
          Check also if "Tunnelblick 3.8.7a (build 5770)" supports the OpenVPN version that is used by pfSEnse :

          [2.5.2-RELEASE][root@pfsense.athome.net]/root: openvpn --version
OpenVPN 2.5.2 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Jun 24 2021
library versions: OpenSSL 1.1.1k-freebsd  25 Mar 2021, LZO 2.10

          The Openvpn version is 2.5.2, identical to the pfSense CE version, that's just a coincidence.
          OpenVPN 2.5.x had a lot of changes compared to 2.4.x (see OpenVPN 2.5.x release notes).

          Hi,

          Thank you for your response, I actually got it to work again after reading some other post that had similar issues.
          I only allowed some AES 192 CBC chipers and checked the tickbox "Do not include OpenVPN 2.5 settings in the client configuration." during export.

          1 Reply Last reply Reply Quote 0
          • First post
            Last post
          Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.