|
|
Stefan Goerres disse:
> Renato Salles wrote:
>> Stefan,
>>
>> Increase the verbose level to 9, and send us the connection log to
>> inspect. Pay attention also to the firewall log, or if your able to
>> "telnet" to the other side without being droped imediately.
>>
>> HTH,
>>
>>
>> RSalles
>>
>
> this is my log file:
>
> Fri Mar 05 09:41:50 2004 0: Current Parameter Settings:
> Fri Mar 05 09:41:50 2004 1: config = 'lnx.ovpn'
> Fri Mar 05 09:41:50 2004 2: show_ciphers = DISABLED
> Fri Mar 05 09:41:50 2004 3: show_digests = DISABLED
> Fri Mar 05 09:41:50 2004 4: genkey = DISABLED
> Fri Mar 05 09:41:50 2004 5: askpass = DISABLED
> Fri Mar 05 09:41:50 2004 6: show_tls_ciphers = DISABLED
> Fri Mar 05 09:41:50 2004 7: proto = 2
> Fri Mar 05 09:41:50 2004 8: local = '[UNDEF]'
> Fri Mar 05 09:41:50 2004 9: remote = 'xxx.xxx'
> Fri Mar 05 09:41:50 2004 10: 109 variation(s) on previous 10 message(s)
> suppressed by --mute
> Fri Mar 05 09:41:50 2004 11: OpenVPN 1.6_beta7 Win32-MinGW [SSL] [LZO]
> built
> on Feb 22 2004
> Fri Mar 05 09:41:50 2004 12: PID packet_id_init seq_backtrack=0
> time_backtrack=0
> Fri Mar 05 09:41:50 2004 13: CRYPTO INFO: n_DES_cblocks=0
> Fri Mar 05 09:41:50 2004 14: CRYPTO INFO: n_DES_cblocks=0
> Fri Mar 05 09:41:50 2004 15: CRYPTO INFO: n_DES_cblocks=0
> Fri Mar 05 09:41:50 2004 16: CRYPTO INFO: n_DES_cblocks=0
> Fri Mar 05 09:41:50 2004 17: Static Encrypt: Cipher 'BF-CBC' initialized
> with 128 bit key
> Fri Mar 05 09:41:50 2004 18: Static Encrypt: CIPHER KEY: 3f34693c 8e1630ef
> 03a1162e e652c8e9
> Fri Mar 05 09:41:50 2004 19: Static Encrypt: CIPHER block_size=8 iv_size=8
> Fri Mar 05 09:41:50 2004 20: Static Encrypt: Using 160 bit message hash
> 'SHA1' for HMAC authentication
> Fri Mar 05 09:41:50 2004 21: Static Encrypt: HMAC KEY: b18a4198 c229ee10
> 59c9c4a7 3237e55d 6e9022eb
> Fri Mar 05 09:41:50 2004 22: Static Encrypt: HMAC size=20 block_size=64
> Fri Mar 05 09:41:50 2004 23: Static Decrypt: Cipher 'BF-CBC' initialized
> with 128 bit key
> Fri Mar 05 09:41:50 2004 24: Static Decrypt: CIPHER KEY: 3f34693c 8e1630ef
> 03a1162e e652c8e9
> Fri Mar 05 09:41:50 2004 25: Static Decrypt: CIPHER block_size=8 iv_size=8
> Fri Mar 05 09:41:50 2004 26: Static Decrypt: Using 160 bit message hash
> 'SHA1' for HMAC authentication
> Fri Mar 05 09:41:50 2004 27: Static Decrypt: HMAC KEY: b18a4198 c229ee10
> 59c9c4a7 3237e55d 6e9022eb
> Fri Mar 05 09:41:50 2004 28: Static Decrypt: HMAC size=20 block_size=64
> Fri Mar 05 09:41:50 2004 29: MTU DYNAMIC mtu=1300, flags=2, 1446 -> 1300
> Fri Mar 05 09:41:50 2004 30: WARNING: normally if you use --mssfix
> and/or --fragment, you should also set --tun-mtu 1500 (currently it is
> 1400)
You can try to set this parameter as sugested to get rid from the warning.
> Fri Mar 05 09:41:50 2004 31: Error opening registry key:
>
This message is very strange for me and i had not notice something like
that in any win32 config log.
I see few possibilities for this: normal user are not allowed to open a
vpn connection (if it is the case, adjust the permissions for the given
user/group). second, a missing registry parameter, and last a corrupted
registry entry. For the 2 last, uninstalling, reboot and re-installing
will probably fix. (But do not take it for granted: wait for one or more
checking in your logs by somebody else in this maillist).
...
SYSTEM\CurrentControlSet\Control\Network\{4D36E972-E325-11CE-BFC1-08002BE103
> 18}\Descriptions\Connection
> Fri Mar 05 09:41:50 2004 32: Error opening registry key:
> SYSTEM\CurrentControlSet\Control\Class\{4D36E972-E325-11CE-BFC1-08002BE10318
> }\0000\ComponentId
> Fri Mar 05 09:41:50 2004 33: cid=pci\ven_14e4&dev_1696
> netcfg={02AAAD65-EBE3-444F-B2C4-F78CFDD55238}
> guid={02AAAD65-EBE3-444F-B2C4-F78CFDD55238}
> Fri Mar 05 09:41:50 2004 34: cid=sw\{eeab7790-c514-11d1-b42b-00805fc1270e}
> netcfg={A70F485A-C639-499D-A5C9-8A06F61893E6}
> guid={02AAAD65-EBE3-444F-B2C4-F78CFDD55238}
> Fri Mar 05 09:41:50 2004 35: cid=ms_l2tpminiport
> netcfg={46C997B4-F772-4449-A798-ECB9BFE458E2}
... more messages like above...
tun-mtu and mssfix beating more and more...
> Fri Mar 05 09:41:50 2004 65: WARNING: in general you should use '--tun-mtu
> 1500 --mssfix 1400' on both sides of the connection if at least one side
> is
> running Windows, unless you have explicitly modified the TAP-Win32 driver
> properties
> Fri Mar 05 09:41:50 2004 66: Data Channel MTU parms [ L:1446 D:1300 EF:46
> EB:0 ET:0 EL:0 ]
> Fri Mar 05 09:41:50 2004 67: Local Options String: 'V3,dev-type
> tun,link-mtu
> 1446,tun-mtu 1400,proto TCPv4_CLIENT,ifconfig 10.3.0.1 10.3.0.2,cipher
> BF-CBC,auth SHA1,keysize 128,secret'
> Fri Mar 05 09:41:50 2004 68: Expected Remote Options String: 'V3,dev-type
> tun,link-mtu 1446,tun-mtu 1400,proto TCPv4_SERVER,ifconfig 10.3.0.2
> 10.3.0.1,cipher BF-CBC,auth SHA1,keysize 128,secret'
> Fri Mar 05 09:41:50 2004 69: Local Options hash (VER=V3): 'd7950b38'
> Fri Mar 05 09:41:50 2004 70: Expected Remote Options hash (VER=V3):
> '91d32896'
> Fri Mar 05 09:41:50 2004 71: STREAM: RESET
> Fri Mar 05 09:41:50 2004 72: STREAM: INIT maxlen=1446
> Fri Mar 05 09:41:50 2004 73: Attempting to establish TCP connection with
> 57.xx.xx.xx:8080
Well, the connection is finally stablished...
> Fri Mar 05 09:41:50 2004 74: TCP connection established with
> 57.xx.xx.xx:8080
> Fri Mar 05 09:41:50 2004 75: Send to HTTP proxy: 'CONNECT xx:563 HTTP/1.0'
> Fri Mar 05 09:41:50 2004 76: Attempting Basic Proxy-Authorization
> Fri Mar 05 09:41:50 2004 77: Send to HTTP proxy: 'Proxy-Authorization:
> Basic
> VTg4MjM5NzpqZW5uaWZlcg=='
> Fri Mar 05 09:41:52 2004 78: HTTP proxy returned: 'HTTP/1.0 200 Connection
> established'
> Fri Mar 05 09:41:54 2004 79: TCPv4_CLIENT link local: [undef]
> Fri Mar 05 09:41:54 2004 80: TCPv4_CLIENT link remote: 57.xx.xx.xx:8080
> Fri Mar 05 09:41:54 2004 81: ENCRYPT IV: de52097c dbcb5551
> Fri Mar 05 09:41:54 2004 82: ENCRYPT FROM: 00000001 40483d52 2a187bf3
> 641eb4cb 07ed2d0a 981fc748
> Fri Mar 05 09:41:54 2004 83: ENCRYPT TO: de52097c dbcb5551 49c39a80
> b54759e9
> 41418602 bf2dfba3 16b668af 0ce55df[more...]
> Fri Mar 05 09:41:54 2004 84: SENT PING
> Fri Mar 05 09:41:54 2004 85: STREAM: SET NEXT, buf=[46,0] next=[46,1446]
> len=-1 maxlen=1446
> Fri Mar 05 09:41:54 2004 86: STREAM: GET NEXT len=1446
> Fri Mar 05 09:41:54 2004 87: WIN32 I/O: Socket Receive queued [1446]
> Fri Mar 05 09:41:54 2004 88: SELECT tr0|tw0|srQ|sw0 1/0
> Fri Mar 05 09:41:54 2004 89: select returned 2
> Fri Mar 05 09:41:54 2004 90: TCPv4_CLIENT WRITE [60] to 57.xx.xx.xx:8080:
> DATA babb25dc 3a68d605 cd136b3d c8ecca42 25b28ce9 de52097c dbcb5551
> 49c39a8[more...]
> Fri Mar 05 09:41:54 2004 91: STREAM: WRITE 60 offset=18
> Fri Mar 05 09:41:54 2004 92: WIN32 I/O: Socket Send immediate return
> [62,62]
> Fri Mar 05 09:41:54 2004 93: TCPv4_CLIENT write returned 62
> Fri Mar 05 09:41:54 2004 94: WIN32 I/O: TAP Read immediate return
> [1400,62]
> Fri Mar 05 09:41:54 2004 95: STREAM: SET NEXT, buf=[46,0] next=[46,1446]
> len=-1 maxlen=1446
> Fri Mar 05 09:41:54 2004 96: SELECT trR|tw0|srQ|swR 1/0
> Fri Mar 05 09:41:54 2004 97: select returned 2
> Fri Mar 05 09:41:54 2004 98: WIN32 I/O: TAP Completion non-queued success
> [62]
> Fri Mar 05 09:41:54 2004 99: read from TUN/TAP returned 62
> Fri Mar 05 09:41:54 2004 100: TUN READ [62]: 4500003e 40940000 80112f64
> 0a030002 c0a8000a 04050035 002ac224 01e0010[more...] md5=5fe52a3a 3fa09b96
> ce0d03ec 3367a57d
> Fri Mar 05 09:41:54 2004 101: 6 variation(s) on previous 10 message(s)
> suppressed by --mute
> Fri Mar 05 09:41:54 2004 102: TCPv4_CLIENT WRITE [100] to
> 57.xx.xx.xx:8080:
...
> Fri Mar 05 09:42:05 2004 216: IP Address OK from 57.xx.xx.xx:8080
> Fri Mar 05 09:42:05 2004 217: DECRYPT IV: c1be23e9 d34cdba7
> Fri Mar 05 09:42:05 2004 218: DECRYPT TO: 00000003 40483d58 287f346b
> d4ef7a81 2d56b8d3 afc5459c 0156332c 6465762[more...]
> Fri Mar 05 09:42:05 2004 219: PID TEST 1078476120:2 1078476120:3
> Fri Mar 05 09:42:05 2004 220: RECEIVED OCC_REPLY
#################################
> Fri Mar 05 09:42:05 2004 221: WARNING: Actual Remote Options ('V3,dev-type
> tun,link-mtu 1300,tun-mtu 1254,proto TCPv4_SERVER,ifconfig 10.3.0.2
> 10.3.0.1,cipher BF-CBC,auth SHA1,keysize 128,secret') are inconsistent
> with
> Expected Remote Options ('V3,dev-type tun,link-mtu 1446,tun-mtu 1400,proto
> TCPv4_SERVER,ifconfig 10.3.0.2 10.3.0.1,cipher BF-CBC,auth SHA1,keysize
> 128,secret')
##################################
This is clear: i've used different tun-mtu and link-mtu values for this
link pair. Fix with the same and go ahead.
....
> Fri Mar 05 09:43:24 2004 464: WIN32 I/O: Socket Send immediate return
> [62,62]
> Fri Mar 05 09:43:24 2004 465: TCPv4_CLIENT write returned 62
> Fri Mar 05 09:43:24 2004 466: STREAM: SET NEXT, buf=[46,0] next=[46,1446]
> len=-1 maxlen=1446
> Fri Mar 05 09:43:24 2004 467: SELECT trQ|twR|srQ|swR 1/0
> Fri Mar 05 09:43:24 2004 468: select returned 2
> Fri Mar 05 09:43:24 2004 469: WIN32 I/O: TAP Completion success [60]
> Fri Mar 05 09:43:24 2004 470: read from TUN/TAP returned 60
> Fri Mar 05 09:43:24 2004 471: TUN READ [60]: 4500003c 41930000 80012d8d
> 0a030002 c0a800f4 0800475c 04000200 6162636[more...] md5=7105cfbd b9b85454
> df83803b b5c8075e
> Fri Mar 05 09:43:24 2004 472: 6 variation(s) on previous 10 message(s)
> suppressed by --mute
> Fri Mar 05 09:43:24 2004 473: TCPv4_CLIENT WRITE [100] to
> 57.xx.xx.xx:8080:
> DATA 0ad48428 f4e592c6 ea734699 d8a4f448 41e16c7b e60fff67 c68d485d
> 49da96c[more...]
> Fri Mar 05 09:43:24 2004 474: STREAM: WRITE 100 offset=18
> Fri Mar 05 09:43:24 2004 475: WIN32 I/O: Socket Completion non-queued
> success [62]
> Fri Mar 05 09:43:24 2004 476: WIN32 I/O: Socket Send immediate return
> [102,102]
> Fri Mar 05 09:43:24 2004 477: TCPv4_CLIENT write returned 102
> Fri Mar 05 09:43:24 2004 478: WIN32 I/O: TAP Read queued [1400]
> Fri Mar 05 09:43:24 2004 479: STREAM: SET NEXT, buf=[46,0] next=[46,1446]
> len=-1 maxlen=1446
> Fri Mar 05 09:43:24 2004 480: SELECT trQ|twR|srQ|swR 1/0
> Fri Mar 05 09:43:24 2004 481: select returned 3
> Fri Mar 05 09:43:24 2004 482: WIN32 I/O: Socket Completion success [102]
> Fri Mar 05 09:43:24 2004 483: STREAM: ADD length_added=102
> Fri Mar 05 09:43:24 2004 484: 4 variation(s) on previous 10 message(s)
> suppressed by --mute
> Fri Mar 05 09:43:24 2004 485: TCPv4_CLIENT READ [100] from
> 57.xx.xx.xx:8080:
> DATA 52c00a0d 793ac107 b4a89a0e 54f5048b c55aec54 697b4f6f 89a5dbee
> e55545d[more...]
> Fri Mar 05 09:43:24 2004 486: IP Address OK from 57.xx.xx.xx:8080
> Fri Mar 05 09:43:24 2004 487: DECRYPT IV: 697b4f6f 89a5dbee
> Fri Mar 05 09:43:24 2004 488: DECRYPT TO: 00000006 40483d58 4500003c
> e86a0000 7f0187b5 c0a800f4 0a030002 00004f5[more...]
> Fri Mar 05 09:43:24 2004 489: PID TEST 1078476120:5 1078476120:6
> Fri Mar 05 09:43:24 2004 490: SELECT trQ|twR|sr0|swR 1/0
> Fri Mar 05 09:43:24 2004 491: select returned 3
> Fri Mar 05 09:43:24 2004 492: TUN WRITE [60]: 4500003c e86a0000 7f0187b5
> c0a800f4 0a030002 00004f5c 04000200 6162636[more...] md5=b93713c4 898d6750
> ca7ba7ce 113d9197
...
> Fri Mar 05 09:43:25 2004 497: TCPv4_CLIENT WRITE [100] to
> 57.xx.xx.xx:8080:
> DATA 82f0d520 5bf913dc 09a3edd2 504e1669 5371c4bc 80d19e6d f7ad9323
> ac89fdc[more...]
> Fri Mar 05 09:43:25 2004 498: STREAM: WRITE 100 offset=18
> Fri Mar 05 09:43:25 2004 499: WIN32 I/O: Socket Completion non-queued
> success [102]
> Fri Mar 05 09:43:25 2004 500: WIN32 I/O: Socket Send immediate return
> [102,102]
> Fri Mar 05 09:43:25 2004 501: TCPv4_CLIENT write returned 102
> Fri Mar 05 09:43:25 2004 502: WIN32 I/O: TAP Read queued [1400]
> Fri Mar 05 09:43:25 2004 503: STREAM: SET NEXT, buf=[46,0] next=[46,1446]
> len=-1 maxlen=1446
...
> Fri Mar 05 09:44:47 2004 1267: Inactivity timeout (--ping-restart),
> restarting
> Fri Mar 05 09:44:47 2004 1268: PID packet_id_free
> Fri Mar 05 09:44:47 2004 1269: Closing TCP/UDP socket
> Fri Mar 05 09:44:47 2004 1270: Restart pause, 10 second(s)
> Fri Mar 05 09:44:57 2004 1271: PID packet_id_init seq_backtrack=0
> time_backtrack=0
> Fri Mar 05 09:44:57 2004 1272: Re-using pre-shared static key
> Fri Mar 05 09:44:57 2004 1273: MTU DYNAMIC mtu=1300, flags=2, 1446 -> 1300
> Fri Mar 05 09:44:57 2004 1274: WARNING: normally if you use --mssfix
> and/or --fragment, you should also set --tun-mtu 1500 (currently it is
> 1400)
> Fri Mar 05 09:44:58 2004 1275: Preserving previous TUN/TAP instance:
> OpenVPN
> Fri Mar 05 09:44:58 2004 1276: Data Channel MTU parms [ L:1446 D:1300
> EF:46
> EB:0 ET:0 EL:0 ]
> Fri Mar 05 09:44:58 2004 1277: Local Options String: 'V3,dev-type
> tun,link-mtu 1446,tun-mtu 1400,proto TCPv4_CLIENT,ifconfig 10.3.0.1
> 10.3.0.2,cipher BF-CBC,auth SHA1,keysize 128,secret'
> Fri Mar 05 09:44:58 2004 1278: Expected Remote Options String:
> 'V3,dev-type
> tun,link-mtu 1446,tun-mtu 1400,proto TCPv4_SERVER,ifconfig 10.3.0.2
> 10.3.0.1,cipher BF-CBC,auth SHA1,keysize 128,secret'
> Fri Mar 05 09:44:58 2004 1279: Local Options hash (VER=V3): 'd7950b38'
> Fri Mar 05 09:44:58 2004 1280: Expected Remote Options hash (VER=V3):
> '91d32896'
> Fri Mar 05 09:44:58 2004 1281: STREAM: RESET
> Fri Mar 05 09:44:58 2004 1282: STREAM: INIT maxlen=1446
> Fri Mar 05 09:44:58 2004 1283: Attempting to establish TCP connection with
> 57.xx.xx.xx:8080
> Fri Mar 05 09:44:58 2004 1284: TCP connection established with
> 57.xx.xx.xx:8080
> Fri Mar 05 09:44:58 2004 1285: Send to HTTP proxy: 'CONNECT xx:563
> HTTP/1.0'
> Fri Mar 05 09:44:58 2004 1286: Attempting Basic Proxy-Authorization
> Fri Mar 05 09:44:58 2004 1287: Send to HTTP proxy: 'Proxy-Authorization:
> Basic VTg4MjM5NzpqZW5uaWZlcg=='
> Fri Mar 05 09:45:00 2004 1288: HTTP proxy returned: 'HTTP/1.0 503 Service
> Unavailable'
> Fri Mar 05 09:45:00 2004 1289: HTTP proxy returned bad status
And here we see a proxy bad status returned
> Fri Mar 05 09:45:00 2004 1290: SIGTERM received, exiting
> Fri Mar 05 09:45:00 2004 1291: PID packet_id_free
> Fri Mar 05 09:45:00 2004 1292: Closing TCP/UDP socket
And the socket being closed.
> Fri Mar 05 09:45:00 2004 1293: Attempting to lock Win32 semaphore
> 'openvpn_netcmd' prior to net shell command (timeout = 600 sec)
> Fri Mar 05 09:45:00 2004 1294: Locked Win32 semaphore 'openvpn_netcmd'
> Fri Mar 05 09:45:00 2004 1295: route DELETE 192.168.0.0
> Fri Mar 05 09:45:01 2004 1296: Releasing Win32 semaphore 'openvpn_netcmd'
> Fri Mar 05 09:45:01 2004 1297: Closing TUN/TAP device
> Fri Mar 05 09:45:01 2004 1298: Attempting CancelIO on TAP-Win32 adapter
> Fri Mar 05 09:45:01 2004 1299: Attempting close of overlapped read event
> on
> TAP-Win32 adapter
> Fri Mar 05 09:45:01 2004 1300: Attempting close of overlapped write event
> on
> TAP-Win32 adapter
> Fri Mar 05 09:45:01 2004 1301: Attempting CloseHandle on TAP-Win32 adapter
> Fri Mar 05 09:45:01 2004 1302: Closing Win32 semaphore 'openvpn_netcmd'
>
> any ideas??
> thx
> Stefan
My sugestion could be: fix what is obviously bad (mssfix and tun-mtu),
check again your connection setings at both sides. If you see again the
registry settings errors as above, you can try to un-install, reboot and
re-install OpenVPN to fix. I'm not sure if the proxy errors are due to
missconfiguration or registry errors.
If these errors remains, come to the list with the log again.
HTH,
RSalles
--
"A well-written program is its own heaven; a poorly-written program is its
own hell."
TAO of Programming - Book 4
____________________________________________
Openvpn-users mailing list
Openvpn-users@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/openvpn-users
|