Tue Feb 28 14:29:00 2012 us=935038 87.xxx.203.xx:60246 Re-using SSL/TLS context
Tue Feb 28 14:29:00 2012 us=935070 87.xxx.203.xx:60246 LZO compression initialized
Tue Feb 28 14:29:00 2012 us=935090 87.xxx.203.xx:60246 MTU DYNAMIC mtu=0, flags=1, 0 -> 138
Tue Feb 28 14:29:00 2012 us=935110 87.xxx.203.xx:60246 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Feb 28 14:29:00 2012 us=935216 87.xxx.203.xx:60246 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Feb 28 14:29:00 2012 us=935238 87.xxx.203.xx:60246 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Feb 28 14:29:00 2012 us=935340 87.xxx.203.xx:60246 PID packet_id_init seq_backtrack=64 time_backtrack=15
Tue Feb 28 14:29:00 2012 us=935362 87.xxx.203.xx:60246 Control Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ]
Tue Feb 28 14:29:00 2012 us=935380 87.xxx.203.xx:60246 MTU DYNAMIC mtu=1300, flags=2, 1546 -> 1300
Tue Feb 28 14:29:00 2012 us=935459 87.xxx.203.xx:60246 MTU DYNAMIC mtu=1300, flags=2, 1546 -> 1300
Tue Feb 28 14:29:00 2012 us=935480 87.xxx.203.xx:60246 Data Channel MTU parms [ L:1546 D:1300 EF:46 EB:135 ET:0 EL:0 AF:3/1 ]
Tue Feb 28 14:29:00 2012 us=935499 87.xxx.203.xx:60246 Fragmentation MTU parms [ L:1546 D:1300 EF:45 EB:135 ET:1 EL:0 AF:3/1 ]
Tue Feb 28 14:29:00 2012 us=935546 87.xxx.203.xx:60246 Local Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Tue Feb 28 14:29:00 2012 us=935565 87.xxx.203.xx:60246 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Tue Feb 28 14:29:00 2012 us=935600 87.xxx.203.xx:60246 Local Options hash (VER=V4): '8e7959c7'
Tue Feb 28 14:29:00 2012 us=935629 87.xxx.203.xx:60246 Expected Remote Options hash (VER=V4): 'c086e1aa'
Tue Feb 28 14:29:00 2012 us=935698 87.xxx.203.xx:60246 SENT PING
Tue Feb 28 14:29:00 2012 us=935726 87.xxx.203.xx:60246 GET INST BY REAL: 87.xxx.203.xx:60246 [created]
Tue Feb 28 14:29:00 2012 us=935752 87.xxx.203.xx:60246 UDPv4 READ [14] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Tue Feb 28 14:29:00 2012 us=935776 87.xxx.203.xx:60246 TLS: Initial packet from [AF_INET]87.xxx.203.xx:60246, sid=1ed49148 9bd73682
Tue Feb 28 14:29:00 2012 us=935817 87.xxx.203.xx:60246 UDPv4 WRITE [26] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Tue Feb 28 14:29:00 2012 us=969410 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:00 2012 us=969438 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 0 ]
Tue Feb 28 14:29:00 2012 us=971448 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:00 2012 us=971473 87.xxx.203.xx:60246 UDPv4 READ [114] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=100
Tue Feb 28 14:29:00 2012 us=971522 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 1 ]
Tue Feb 28 14:29:00 2012 us=971988 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:00 2012 us=972013 87.xxx.203.xx:60246 UDPv4 READ [17] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=3
Tue Feb 28 14:29:00 2012 us=976626 87.xxx.203.xx:60246 UDPv4 WRITE [126] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ 2 ] pid=1 DATA len=100
Tue Feb 28 14:29:00 2012 us=976707 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=100
Tue Feb 28 14:29:00 2012 us=976765 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=100
Tue Feb 28 14:29:00 2012 us=976821 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=100
Tue Feb 28 14:29:00 2012 us=976861 87.xxx.203.xx:60246 ACK output sequence broken: [5] 1 2 3 4
Tue Feb 28 14:29:01 2012 us=16091 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:01 2012 us=16117 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 1 ]
Tue Feb 28 14:29:01 2012 us=16181 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=5 DATA len=100
Tue Feb 28 14:29:01 2012 us=16228 87.xxx.203.xx:60246 ACK output sequence broken: [6] 5 2 3 4
Tue Feb 28 14:29:01 2012 us=16261 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:01 2012 us=16283 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 2 ]
Tue Feb 28 14:29:01 2012 us=16328 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=6 DATA len=100

.. repeated P_ACK_V1 P_CONTROL_V1 stuff

Tue Feb 28 14:29:04 2012 us=707693 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:04 2012 us=707718 87.xxx.203.xx:60246 UDPv4 READ [114] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=100
Tue Feb 28 14:29:04 2012 us=707757 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 7 ]
Tue Feb 28 14:29:04 2012 us=708605 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:04 2012 us=708656 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:04 2012 us=708790 87.xxx.203.xx:60246 PLUGIN_CALL: PRE type=PLUGIN_AUTH_USER_PASS_VERIFY
Tue Feb 28 14:29:04 2012 us=708810 87.xxx.203.xx:60246 ARGV[0] = '/etc/openvpn/radiusplugin.so'
Tue Feb 28 14:29:04 2012 us=708827 87.xxx.203.xx:60246 ENVP[0] = 'auth_control_file=/tmp/openvpn_acf_9d37e38b6286cf6dbb46510e6794b908.tmp'
Tue Feb 28 14:29:04 2012 us=708844 87.xxx.203.xx:60246 ENVP[1] = 'untrusted_port=60246'
Tue Feb 28 14:29:04 2012 us=708860 87.xxx.203.xx:60246 ENVP[2] = 'untrusted_ip=87.xxx.203.xx'
Tue Feb 28 14:29:04 2012 us=708877 87.xxx.203.xx:60246 ENVP[4] = 'username=user1234'
Tue Feb 28 14:29:04 2012 us=708893 87.xxx.203.xx:60246 ENVP[5] = 'remote_port_1=1194'
Tue Feb 28 14:29:04 2012 us=708910 87.xxx.203.xx:60246 ENVP[6] = 'local_port_1=9300'
Tue Feb 28 14:29:04 2012 us=708926 87.xxx.203.xx:60246 ENVP[7] = 'local_1=172.xxx.xxx.xxx'
Tue Feb 28 14:29:04 2012 us=708943 87.xxx.203.xx:60246 ENVP[8] = 'proto_1=udp'
Tue Feb 28 14:29:04 2012 us=708959 87.xxx.203.xx:60246 ENVP[9] = 'daemon_pid=1182'
Tue Feb 28 14:29:04 2012 us=708975 87.xxx.203.xx:60246 ENVP[10] = 'daemon_start_time=1330424788'
Tue Feb 28 14:29:04 2012 us=708992 87.xxx.203.xx:60246 ENVP[11] = 'daemon_log_redirect=1'
Tue Feb 28 14:29:04 2012 us=709008 87.xxx.203.xx:60246 ENVP[12] = 'daemon=1'
Tue Feb 28 14:29:04 2012 us=709024 87.xxx.203.xx:60246 ENVP[13] = 'verb=7'
Tue Feb 28 14:29:04 2012 us=709040 87.xxx.203.xx:60246 ENVP[14] = 'config=/etc/openvpn/fixedip.conf'
Tue Feb 28 14:29:04 2012 us=709057 87.xxx.203.xx:60246 ENVP[15] = 'ifconfig_local=172.xxx.0.1'
Tue Feb 28 14:29:04 2012 us=709073 87.xxx.203.xx:60246 ENVP[16] = 'ifconfig_remote=172.21.0.2'
Tue Feb 28 14:29:04 2012 us=709089 87.xxx.203.xx:60246 ENVP[17] = 'script_context=init'
Tue Feb 28 14:29:04 2012 us=709105 87.xxx.203.xx:60246 ENVP[18] = 'tun_mtu=1500'
Tue Feb 28 14:29:04 2012 us=709122 87.xxx.203.xx:60246 ENVP[19] = 'link_mtu=1542'
Tue Feb 28 14:29:04 2012 us=709138 87.xxx.203.xx:60246 ENVP[20] = 'dev=tun0'
Tue Feb 28 14:29:04 2012 RADIUS-PLUGIN: FOREGROUND: Key: 87.xxx.203.xx:60246.
Tue Feb 28 14:29:23 2012 us=649026 87.xxx.203.xx:60246 PLUGIN_CALL: POST /etc/openvpn/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Tue Feb 28 14:29:23 2012 us=649076 87.xxx.203.xx:60246 TLS: Username/Password authentication succeeded for username 'user1234' [CN SET]
Tue Feb 28 14:29:23 2012 us=649129 87.xxx.203.xx:60246 TEST FILE '/etc/openvpn/ccd/user1234' [1]
Tue Feb 28 14:29:23 2012 us=649222 87.xxx.203.xx:60246 Client pre_master: d4711f11 b2951250 598cea61 b09e41b4 331383f9 fe799cb1 796b67e2 c67a898a 476555bc 719d22cf c6e5a8a0 5f461c58
Tue Feb 28 14:29:23 2012 us=649250 87.xxx.203.xx:60246 Client random1: 7a6e7301 f2d4c7f8 cc72e4af 5089dadf b04d9d99 7363ec5d a1db7b4b 123cca1b
Tue Feb 28 14:29:23 2012 us=649275 87.xxx.203.xx:60246 Client random2: b3c6bd31 d8597bf1 4cb70012 06236f68 9dc820de 599027c1 4819cc0c 5b810b90
Tue Feb 28 14:29:23 2012 us=649306 87.xxx.203.xx:60246 Server pre_master: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Tue Feb 28 14:29:23 2012 us=649330 87.xxx.203.xx:60246 Server random1: af27d74a ed62b335 1bbdce40 d67eceb4 3c9659e7 08e794cb b33c9702 b4e6b233
Tue Feb 28 14:29:23 2012 us=649355 87.xxx.203.xx:60246 Server random2: 3bbaba76 11e28160 0eb410be 7c5cbda5 4094fd85 eb7e0eca 265ec9f5 71707361
Tue Feb 28 14:29:23 2012 us=649380 87.xxx.203.xx:60246 tls1_P_hash sec: d4711f11 b2951250 598cea61 b09e41b4 331383f9 fe799cb1
Tue Feb 28 14:29:23 2012 us=649419 87.xxx.203.xx:60246 tls1_P_hash seed: 4f70656e 56504e20 6d617374 65722073 65637265 747a6e73 01f2d4c7 f8cc72e4 af5089da dfb04d9d 997363ec 5da1db7b 4b123cca 1baf27d7 4aed62b3 351bbdce 40d67ece b43c9659 e7
08e794 cbb33c97 02b4e6b2 33
Tue Feb 28 14:29:23 2012 us=649464 87.xxx.203.xx:60246 tls1_P_hash out: 2126ca28 2bda70a8 c57ac0f3 01819470 dc666779 7b316797 288369cc be0289f4 e72c6daf ed7d2c07 e89130dd a173cdf7
Tue Feb 28 14:29:23 2012 us=649488 87.xxx.203.xx:60246 tls1_P_hash sec: 796b67e2 c67a898a 476555bc 719d22cf c6e5a8a0 5f461c58
Tue Feb 28 14:29:23 2012 us=649526 87.xxx.203.xx:60246 tls1_P_hash seed: 4f70656e 56504e20 6d617374 65722073 65637265 747a6e73 01f2d4c7 f8cc72e4 af5089da dfb04d9d 997363ec 5da1db7b 4b123cca 1baf27d7 4aed62b3 351bbdce 40d67ece b43c9659 e7
08e794 cbb33c97 02b4e6b2 33
Tue Feb 28 14:29:23 2012 us=649570 87.xxx.203.xx:60246 tls1_P_hash out: ee12698f 9b964244 5332b832 436c42fb 73a258e1 a5c7eb58 1e4cdca7 fed8b26e c9da7364 1bc47736 79a41986 b0c0aec4
Tue Feb 28 14:29:23 2012 us=649600 87.xxx.203.xx:60246 tls1_PRF out[48]: cf34a3a7 b04c32ec 964878c1 42edd68b afc43f98 def68ccf 36cfb56b 40da3b9a 2ef61ecb f6b95b31 9135295b 11b36333
Tue Feb 28 14:29:23 2012 us=649623 87.xxx.203.xx:60246 tls1_P_hash sec: cf34a3a7 b04c32ec 964878c1 42edd68b afc43f98 def68ccf
Tue Feb 28 14:29:23 2012 us=649669 87.xxx.203.xx:60246 tls1_P_hash seed: 4f70656e 56504e20 6b657920 65787061 6e73696f 6eb3c6bd 31d8597b f14cb700 1206236f 689dc820 de599027 c14819cc 0c5b810b 903bbaba 7611e281 600eb410 be7c5cbd a54094fd 85
eb7e0e ca265ec9 f5717073 611ed491 489bd736 82a19ea9 815974a5 64
Tue Feb 28 14:29:23 2012 us=649781 87.xxx.203.xx:60246 tls1_P_hash out: a8331071 56aa1eda 0d74d5a8 a10361f4 0c88e393 7e9e3d3d 6f5f6d3c 6da3641d adb4851d 8aa34e2d 4213b9b3 cfc0de83 35174073 b00f6e71 22d54a5d c6f3e4a3 a979e673 759a9f3b 54b
55fb0 faff2d53 752828f4 dcc5292b 67fc63a0 5c589ccf ec666911 c20606de 37acc406 af46a966 e1cfc467 a4506589 3f28104a e0789e3d 6203747c a6e7067a e4583eb9 fa63f329 79347dee 7fa5dc0a 83fc2fc8 99514537 2dff8c49 402e792a 46066486 cad1ec10 673d23
46 f85de4d7 f9cac53a 1a2675b5 85cb945c ee8a89b2 141d0f1e b6d5116c 321782fa ed0d2b84 52d1c73d 10ce2328 1a130475 a9fc8c0c e734fad9 f487c99f 6880aa57 f7d57484 a8d0affc 6aae30c9
Tue Feb 28 14:29:23 2012 us=649807 87.xxx.203.xx:60246 tls1_P_hash sec: 36cfb56b 40da3b9a 2ef61ecb f6b95b31 9135295b 11b36333
Tue Feb 28 14:29:23 2012 us=649861 87.xxx.203.xx:60246 tls1_P_hash seed: 4f70656e 56504e20 6b657920 65787061 6e73696f 6eb3c6bd 31d8597b f14cb700 1206236f 689dc820 de599027 c14819cc 0c5b810b 903bbaba 7611e281 600eb410 be7c5cbd a54094fd 85
eb7e0e ca265ec9 f5717073 611ed491 489bd736 82a19ea9 815974a5 64
Tue Feb 28 14:29:23 2012 us=649973 87.xxx.203.xx:60246 tls1_P_hash out: 1eaad7db dbf09bc0 a425f3cc 19c7bb89 5bbac30d 0fe3adb1 f584a51c 8469fe39 d351f195 18230335 47f5eea1 f147d290 5ac01159 d6ab4075 e48dfb6a 02b637e9 b40ca931 56152c08 11b
da177 2dbdebf6 9c12f0cb 9b168853 8c25b09e 852b3749 8560b010 e9a44c61 d7951809 6ff7b51a 178a2d00 b5bc63ab df6db774 35b8d627 a2f8352d 958d352a 28e539ab ad22a905 695d2214 7394621b 2bdace3d 33e13aa9 bfb2b3d4 6efc121d 6443c9a0 5f9350dd a47e03
40 93d27b9d d0e2d404 8584ce6b 4d84aec7 27109e68 5639eef8 a220cae4 8aaaf50a cd159ecf 07782aa6 10aad985 eb19eeb7 35e0db2b 33a18b95 032788a7 fab0a39d d83e9918 7f7906b9 9d5a2afb
Tue Feb 28 14:29:23 2012 us=650058 87.xxx.203.xx:60246 tls1_PRF out[256]: b69fc7ab 8d5a851a a9512664 b8c4da7d 5732209e 717d908c 9adbc820 e9ca9a24 7ee57488 92804d18 05e65712 3e870c13 6fd7512a 66a42e04 c658b137 c445d34a 1d754f42 238fb333 4
508fec7 d742c6a5 e93ad83f 47d3a178 ebd9d33e d973ab86 6906d901 2ba24abf e039dc0f c0b11c7c f645e967 11ec0622 e045a73e d5c0481a c0fb4151 336a3350 ccbd0712 57415a2c 10695ffa 0c31be11 a826e1f5 aab07f9e 924d3f9d 2ed26b37 2245ad26 9542bccd c343
2006 6b8f9f4a 2928113e 9fa2bbde c84f3a9b c99a17da 4224e1e6 14fadb21 b8bd77f0 2018b54b 55a9ed9b 0064faad f10aeac2 9c1c5727 d495714c f7a04138 923009ca 2febed9c d7a9a945 f7f41a32
Tue Feb 28 14:29:23 2012 us=650083 87.xxx.203.xx:60246 Master Encrypt (cipher): b69fc7ab 8d5a851a a9512664 b8c4da7d
Tue Feb 28 14:29:23 2012 us=650105 87.xxx.203.xx:60246 Master Encrypt (hmac): 1d754f42 238fb333 4508fec7 d742c6a5 e93ad83f
Tue Feb 28 14:29:23 2012 us=650126 87.xxx.203.xx:60246 Master Decrypt (cipher): c0fb4151 336a3350 ccbd0712 57415a2c
Tue Feb 28 14:29:23 2012 us=650147 87.xxx.203.xx:60246 Master Decrypt (hmac): c84f3a9b c99a17da 4224e1e6 14fadb21 b8bd77f0
Tue Feb 28 14:29:23 2012 us=650166 87.xxx.203.xx:60246 CRYPTO INFO: n_DES_cblocks=0
Tue Feb 28 14:29:23 2012 us=650183 87.xxx.203.xx:60246 CRYPTO INFO: n_DES_cblocks=0
Tue Feb 28 14:29:23 2012 us=650199 87.xxx.203.xx:60246 CRYPTO INFO: n_DES_cblocks=0
Tue Feb 28 14:29:23 2012 us=650215 87.xxx.203.xx:60246 CRYPTO INFO: n_DES_cblocks=0
Tue Feb 28 14:29:23 2012 us=650298 87.xxx.203.xx:60246 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Tue Feb 28 14:29:23 2012 us=650319 87.xxx.203.xx:60246 Data Channel Encrypt: CIPHER KEY: c0fb4151 336a3350 ccbd0712 57415a2c
Tue Feb 28 14:29:23 2012 us=650337 87.xxx.203.xx:60246 Data Channel Encrypt: CIPHER block_size=8 iv_size=8
Tue Feb 28 14:29:23 2012 us=650357 87.xxx.203.xx:60246 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Feb 28 14:29:23 2012 us=650380 87.xxx.203.xx:60246 Data Channel Encrypt: HMAC KEY: c84f3a9b c99a17da 4224e1e6 14fadb21 b8bd77f0
Tue Feb 28 14:29:23 2012 us=650397 87.xxx.203.xx:60246 Data Channel Encrypt: HMAC size=20 block_size=64
Tue Feb 28 14:29:23 2012 us=650471 87.xxx.203.xx:60246 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Tue Feb 28 14:29:23 2012 us=650492 87.xxx.203.xx:60246 Data Channel Decrypt: CIPHER KEY: b69fc7ab 8d5a851a a9512664 b8c4da7d
Tue Feb 28 14:29:23 2012 us=650509 87.xxx.203.xx:60246 Data Channel Decrypt: CIPHER block_size=8 iv_size=8
Tue Feb 28 14:29:23 2012 us=650529 87.xxx.203.xx:60246 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Feb 28 14:29:23 2012 us=650552 87.xxx.203.xx:60246 Data Channel Decrypt: HMAC KEY: 1d754f42 238fb333 4508fec7 d742c6a5 e93ad83f
Tue Feb 28 14:29:23 2012 us=650569 87.xxx.203.xx:60246 Data Channel Decrypt: HMAC size=20 block_size=64
Tue Feb 28 14:29:23 2012 us=656075 87.xxx.203.xx:60246 UDPv4 WRITE [126] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ 8 ] pid=45 DATA len=100
Tue Feb 28 14:29:23 2012 us=656179 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=46 DATA len=100
Tue Feb 28 14:29:23 2012 us=656227 87.xxx.203.xx:60246 UDPv4 WRITE [96] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=47 DATA len=82
Tue Feb 28 14:29:23 2012 us=660961 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=660985 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:23 2012 us=661026 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 8 ]
Tue Feb 28 14:29:23 2012 us=666310 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=666334 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:23 2012 us=666385 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 8 ]
Tue Feb 28 14:29:23 2012 us=672992 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=673016 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:23 2012 us=673058 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 8 ]
Tue Feb 28 14:29:23 2012 us=681579 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=681603 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:23 2012 us=681642 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 8 ]
Tue Feb 28 14:29:23 2012 us=689261 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=689285 87.xxx.203.xx:60246 UDPv4 READ [60] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=46
Tue Feb 28 14:29:23 2012 us=689323 87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 8 ]
Tue Feb 28 14:29:23 2012 us=700732 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=700756 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 46 ]
Tue Feb 28 14:29:23 2012 us=700797 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:23 2012 us=700819 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 47 ]
Tue Feb 28 14:29:25 2012 us=8521 87.xxx.203.xx:60246 UDPv4 WRITE [114] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=45 DATA len=100
Tue Feb 28 14:29:25 2012 us=47194 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:25 2012 us=47218 87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 45 ]
Tue Feb 28 14:29:25 2012 us=47246 87.xxx.203.xx:60246 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA
Tue Feb 28 14:29:25 2012 us=47288 87.xxx.203.xx:60246 [user1234] Peer Connection Initiated with [AF_INET]87.xxx.203.xx:60246
Tue Feb 28 14:29:25 2012 us=47399 user1234/87.xxx.203.xx:60246 TEST FILE '/etc/openvpn/ccd/user1234' [1]
Tue Feb 28 14:29:25 2012 us=47417 user1234/87.xxx.203.xx:60246 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/ccd/user1234
Tue Feb 28 14:29:25 2012 us=47656 user1234/87.xxx.203.xx:60246 PLUGIN_CALL: PRE type=PLUGIN_CLIENT_CONNECT
Tue Feb 28 14:29:25 2012 us=47676 user1234/87.xxx.203.xx:60246 ARGV[0] = '/etc/openvpn/radiusplugin.so'
Tue Feb 28 14:29:25 2012 us=47693 user1234/87.xxx.203.xx:60246 ARGV[1] = '/tmp/openvpn_cc_64d3bb59f27557e61d2d8a61cf6be233.tmp'
Tue Feb 28 14:29:25 2012 us=47710 user1234/87.xxx.203.xx:60246 ENVP[0] = 'time_unix=1330435740'
Tue Feb 28 14:29:25 2012 us=47726 user1234/87.xxx.203.xx:60246 ENVP[1] = 'time_ascii=Tue Feb 28 14:29:00 2012'
Tue Feb 28 14:29:25 2012 us=47742 user1234/87.xxx.203.xx:60246 ENVP[2] = 'ifconfig_pool_local_ip=172.21.154.97'
Tue Feb 28 14:29:25 2012 us=47759 user1234/87.xxx.203.xx:60246 ENVP[3] = 'ifconfig_pool_remote_ip=172.xxx.xxx.xxx'
Tue Feb 28 14:29:25 2012 us=47775 user1234/87.xxx.203.xx:60246 ENVP[4] = 'trusted_port=60246'
Tue Feb 28 14:29:25 2012 us=47791 user1234/87.xxx.203.xx:60246 ENVP[5] = 'trusted_ip=87.xxx.203.xx'
Tue Feb 28 14:29:25 2012 us=47807 user1234/87.xxx.203.xx:60246 ENVP[6] = 'common_name=user1234'
Tue Feb 28 14:29:25 2012 us=47824 user1234/87.xxx.203.xx:60246 ENVP[7] = 'username=user1234'
Tue Feb 28 14:29:25 2012 us=47840 user1234/87.xxx.203.xx:60246 ENVP[8] = 'auth_control_file=/tmp/openvpn_acf_9d37e38b6286cf6dbb46510e6794b908.tmp'
Tue Feb 28 14:29:25 2012 us=47857 user1234/87.xxx.203.xx:60246 ENVP[9] = 'untrusted_port=60246'
Tue Feb 28 14:29:25 2012 us=47873 user1234/87.xxx.203.xx:60246 ENVP[10] = 'untrusted_ip=87.xxx.203.xx'
Tue Feb 28 14:29:25 2012 us=47889 user1234/87.xxx.203.xx:60246 ENVP[11] = 'remote_port_1=1194'
Tue Feb 28 14:29:25 2012 us=47906 user1234/87.xxx.203.xx:60246 ENVP[12] = 'local_port_1=9300'
Tue Feb 28 14:29:25 2012 us=47921 user1234/87.xxx.203.xx:60246 ENVP[13] = 'local_1=172.xxx.xxx.xxx'
Tue Feb 28 14:29:25 2012 us=47938 user1234/87.xxx.203.xx:60246 ENVP[14] = 'proto_1=udp'
Tue Feb 28 14:29:25 2012 us=47954 user1234/87.xxx.203.xx:60246 ENVP[15] = 'daemon_pid=1182'
Tue Feb 28 14:29:25 2012 us=47970 user1234/87.xxx.203.xx:60246 ENVP[16] = 'daemon_start_time=1330424788'
Tue Feb 28 14:29:25 2012 us=47986 user1234/87.xxx.203.xx:60246 ENVP[17] = 'daemon_log_redirect=1'
Tue Feb 28 14:29:25 2012 us=48002 user1234/87.xxx.203.xx:60246 ENVP[18] = 'daemon=1'
Tue Feb 28 14:29:25 2012 us=48018 user1234/87.xxx.203.xx:60246 ENVP[19] = 'verb=7'
Tue Feb 28 14:29:25 2012 us=48035 user1234/87.xxx.203.xx:60246 ENVP[20] = 'config=/etc/openvpn/fixedip.conf'
Tue Feb 28 14:29:25 2012 us=48051 user1234/87.xxx.203.xx:60246 ENVP[21] = 'ifconfig_local=172.xxx.0.1'
Tue Feb 28 14:29:25 2012 us=48067 user1234/87.xxx.203.xx:60246 ENVP[22] = 'ifconfig_remote=172.21.0.2'
Tue Feb 28 14:29:25 2012 us=48083 user1234/87.xxx.203.xx:60246 ENVP[23] = 'script_context=init'
Tue Feb 28 14:29:25 2012 us=48099 user1234/87.xxx.203.xx:60246 ENVP[24] = 'tun_mtu=1500'
Tue Feb 28 14:29:25 2012 us=48115 user1234/87.xxx.203.xx:60246 ENVP[25] = 'link_mtu=1542'
Tue Feb 28 14:29:25 2012 us=48143 user1234/87.xxx.203.xx:60246 ENVP[26] = 'dev=tun0'
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: FOREGROUND: OPENVPN_PLUGIN_CLIENT_CONNECT is called.
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: FOREGROUND: Key: 87.xxx.203.xx:60246.
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: FOREGROUND: Set FramedIP to the IP (172.xxx.xxx.xxx) OpenVPN assigned to the user user1234
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: FOREGROUND: Add user for accounting: username: user1234, commonname: user1234
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: BACKGROUND-ACCT: Get ACCOUNTING_RESPONSE-Packet.
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: BACKGROUND-ACCT: Scheduler: Update packet for User user9999 was send.
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: BACKGROUND-ACCT: Scheduler: Update for User user3333.
Tue Feb 28 14:29:25 2012 RADIUS-PLUGIN: BACKGROUND ACCT: Scheduler: Read Statusfile.
Tue Feb 28 14:29:35 2012 RADIUS-PLUGIN: BACKGROUND-ACCT: Get ACCOUNTING_RESPONSE-Packet.
Tue Feb 28 14:29:35 2012 RADIUS-PLUGIN: BACKGROUND-ACCT: Scheduler: Update packet for User user3333 was send.
Tue Feb 28 14:29:35 2012 RADIUS-PLUGIN: BACKGROUND ACCT: Get a command.
Tue Feb 28 14:29:35 2012 RADIUS-PLUGIN: BACKGROUND ACCT: New User.
Tue Feb 28 14:29:35 2012 RADIUS-PLUGIN: BACKGROUND ACCT: New user acct: username: user1234, interval: 1800, calling station: 87.xxx.203.xx, commonname: user1234, framed ip: 172.xxx.xxx.xxx.
Tue Feb 28 14:29:40 2012 RADIUS-PLUGIN: BACKGROUND ACCT: Error: Start packet couldn't send.
Tue Feb 28 14:29:40 2012 Error: RADIUS-PLUGIN: FOREGROUND: Accounting failed for user:user1234!
Tue Feb 28 14:29:40 2012 us=711324 user1234/87.xxx.203.xx:60246 PLUGIN_CALL: POST /etc/openvpn/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=1
Tue Feb 28 14:29:40 2012 us=711346 user1234/87.xxx.203.xx:60246 PLUGIN_CALL: plugin function PLUGIN_CLIENT_CONNECT failed with status 1: /etc/openvpn/radiusplugin.so
Tue Feb 28 14:29:40 2012 us=711367 user1234/87.xxx.203.xx:60246 WARNING: client-connect plugin call failed
Tue Feb 28 14:29:40 2012 us=711508 MULTI: REAP range 240 -> 256
Tue Feb 28 14:29:40 2012 us=730955 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:40 2012 us=730979 user1234/87.xxx.203.xx:60246 UDPv4 READ [104] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=9 DATA len=90
Tue Feb 28 14:29:40 2012 us=731036 user1234/87.xxx.203.xx:60246 PUSH: Received control message: 'PUSH_REQUEST'
Tue Feb 28 14:29:40 2012 us=731056 user1234/87.xxx.203.xx:60246 Delayed exit in 5 seconds
Tue Feb 28 14:29:40 2012 us=731102 user1234/87.xxx.203.xx:60246 SENT CONTROL [user1234]: 'AUTH_FAILED' (status=1)
Tue Feb 28 14:29:40 2012 us=731132 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 9 ]
Tue Feb 28 14:29:40 2012 us=731186 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [104] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=48 DATA len=90

...

Tue Feb 28 14:29:40 2012 us=757401 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 11 ]
Tue Feb 28 14:29:40 2012 us=757450 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=50 DATA len=74
Tue Feb 28 14:29:41 2012 us=86656 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:41 2012 us=86709 user1234/87.xxx.203.xx:60246 UDPv4 READ [22] from [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 48 ]
Tue Feb 28 14:29:41 2012 us=86818 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:41 2012 us=86860 user1234/87.xxx.203.xx:60246 UDPv4 READ [61] from [AF_INET]87.xxx.203.xx:60246: P_DATA_V1 kid=0 DATA len=60
Tue Feb 28 14:29:41 2012 us=86893 user1234/87.xxx.203.xx:60246 TLS: tls_pre_decrypt, key_id=0, IP=[AF_INET]87.xxx.203.xx:60246
Tue Feb 28 14:29:41 2012 us=86937 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:41 2012 us=86972 user1234/87.xxx.203.xx:60246 UDPv4 READ [88] from [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=12 DATA len=74
Tue Feb 28 14:29:41 2012 us=87114 user1234/87.xxx.203.xx:60246 PUSH: Received control message: 'PUSH_REQUEST'
Tue Feb 28 14:29:41 2012 us=87140 user1234/87.xxx.203.xx:60246 Delayed exit in 5 seconds
Tue Feb 28 14:29:41 2012 us=87252 user1234/87.xxx.203.xx:60246 SENT CONTROL [user1234]: 'AUTH_FAILED' (status=1)
Tue Feb 28 14:29:41 2012 us=87311 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [22] to [AF_INET]87.xxx.203.xx:60246: P_ACK_V1 kid=0 [ 12 ]
Tue Feb 28 14:29:41 2012 us=87434 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=51 DATA len=74
Tue Feb 28 14:29:41 2012 us=87524 GET INST BY REAL: 87.xxx.203.xx:60246 [succeeded]
Tue Feb 28 14:29:41 2012 us=87560 user1234/87.xxx.203.xx:60246 UDPv4 READ [61] from [AF_INET]87.xxx.203.xx:60246: P_DATA_V1 kid=0 DATA len=60
Tue Feb 28 14:29:41 2012 us=87586 user1234/87.xxx.203.xx:60246 TLS: tls_pre_decrypt, key_id=0, IP=[AF_INET]87.xxx.203.xx:60246
Tue Feb 28 14:29:42 2012 us=474417 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=49 DATA len=74
Tue Feb 28 14:29:42 2012 us=474494 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=50 DATA len=74
Tue Feb 28 14:29:43 2012 us=398512 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=51 DATA len=74
Tue Feb 28 14:29:44 2012 us=146533 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=49 DATA len=74
Tue Feb 28 14:29:44 2012 us=146617 user1234/87.xxx.203.xx:60246 UDPv4 WRITE [88] to [AF_INET]87.xxx.203.xx:60246: P_CONTROL_V1 kid=0 [ ] pid=50 DATA len=74
Tue Feb 28 14:29:46 2012 us=6155 user1234/87.xxx.203.xx:60246 SIGTERM[soft,delayed-exit] received, client-instance exiting