Hi, I am running into a issue when attempting to establish a VPN connection from windows clients (XP, Win7, Server 2K3). I can access the web_client service just fine. I can download and install the 1.8.3 client just fine. When establishing the connection, I get a
JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[] on the systray icon. So far, this has been consistent across Windows clients only (XP, Win7, Server 2K3 R2). I cannot replicate the issue with my Mac (OSX LIon) where I can connect without a hitch. I have tried to research this issue to no avail. Both ports 443 and 1194 are being forwarded. Obviously, everything would appear to be working at the far end since my Mac connects without issue. Below are details re. my setup as well as a dump of the capi.log client log usernames/host info substituted.
Hoping someone can shed some light. Many thanks in advance.
-Access Server version: 1.8.3 (running on Debian [Lenny]
-Authenticate users with: pam
-Accepting VPN client connections on IP address: eth0: 172.16.2.2
-Port for VPN client connections: tcp/443, udp/1194
-OSI Layer: 3 (routing/NAT)
-Clients access private subnets using: NAT
2012-05-04 17:06:21-0400 [-] Log opened.
2012-05-04 17:06:21-0400 [-] Network up
2012-05-04 17:06:21-0400 [-] C:\Program Files\OpenVPN Technologies\OpenVPN Client\core\library.zip\pyovpn\linux\distroname.py:1: exceptions.DeprecationWarning: The popen2 module is deprecated. Use the subprocess module.
2012-05-04 17:06:21-0400 [-] ProfileManager: Error reading bundled profile: [Errno 2] No such file or directory: 'C:\\Program Files\\OpenVPN Technologies\\OpenVPN Client\\etc\\bundled.json': client/profman:676,util/simplefile:25,util/simplefile:17 (exceptions.IOError)
2012-05-04 17:06:21-0400 [-] Schedule swupdate monitor in 120 seconds, range=(120,None), error=False, initial=True
2012-05-04 17:06:21-0400 [-] Updating C:\WINDOWS\system32\drivers\etc\hosts with [(u'client.openvpn.net', u'127.94.0.1'), (u'openvpn-client.myvpnhost.dyndns.org', u'127.94.0.2')]
2012-05-04 17:06:21-0400 [-] Starting AS Client API 1.8.3/MSI
2012-05-04 17:06:21-0400 [-] twisted.web.server.Site starting on 946
2012-05-04 17:06:21-0400 [-] twisted.web.server.Site starting on 946
2012-05-04 17:06:21-0400 [-] twisted.web.server.Site starting on 944
2012-05-04 17:06:22-0400 [HTTPChannel,0,127.0.0.1] *** API CALL f=xmlrpc_GetPreferences args=[] kw={} ret={'proxy_auto': True, 'exec_admin_domain': '', 'update_base_url': 'http://swupdate.openvpn.net/updates', 'log_append': False, 'enable_xd_proxy': True, 'basic_client': True, 'auth_allow_cache_pw': True, 'restrict_domain': '*', 'proxy_auth_allow_basic': True, 'proto_force': '', 'allow_ssl_v2': False, 'connect_timeout': 60, 'implicit_elevation': False, 'exec_user_domain': '*', 'universal_sessions_are_global': False, 'verb': '', 'proxy_auth_allow_save_pw': True, 'user_may_trust_cert': True, 'silent_update': False, 'route_nopull': False, 'enable_connect': True, 'notify_update': True, 'user_hostspec': '*', 'allow_web_import': True}
2012-05-04 17:06:22-0400 [HTTPChannel,1,127.0.0.1] *** API CALL f=xmlrpc_TrackActiveProfiles args=[True] kw={} ret='sess_TrackActiveProfiles_l3rbieeXCvfGncDE_1'
2012-05-04 17:06:22-0400 [HTTPChannel,2,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_l3rbieeXCvfGncDE_1', 10] kw={} ret=[{'timestamp': 1336165582, 'state': 'add_profile', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:06:22-0400 [HTTPChannel,3,127.0.0.1] *** API CALL f=xmlrpc_ProfileProperties args=['myvpnhost_dyndns_org_dynamic_p7364'] kw={} ret={'hash': '93d6e22cdf691a8c466ffbb2af66ed0f33ce334110d01c5fad7f84df34b6489b', 'name': 'myvpnhost.dyndns.org/Dynamic', 'global': True, 'host': 'myvpnhost.dyndns.org', 'owner': u'jamesl', 'org': 'myvpnhost.local', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'access_allowed': True}
2012-05-04 17:06:23-0400 [-] create_desktop_process: ovpntray.exe is already running in session 1
2012-05-04 17:06:24-0400 [HTTPChannel,5,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_l3rbieeXCvfGncDE_1', 10] kw={} ret=[{'timestamp': 1336165584, 'state': 'connect', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:06:24-0400 [HTTPChannel,5,127.0.0.1] *** API CALL f=xmlrpc_Connect args=[{'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'dynamic', 'non_interactive': False}, ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT'], {}] kw={} ret='sess_myvpnhost_dyndns_org_dynamic_p7364_CqOcyZPLgABsk9oz_1'
2012-05-04 17:06:24-0400 [HTTPChannel,6,127.0.0.1] *** API CALL f=xmlrpc_ConnectActive args=['myvpnhost_dyndns_org_dynamic_p7364', ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT'], 'pending'] kw={} ret='sess_myvpnhost_dyndns_org_dynamic_p7364_spskQTcqfXzvnJ5S_2'
2012-05-04 17:06:24-0400 [HTTPChannel,7,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_spskQTcqfXzvnJ5S_2', 10] kw={} ret=[{'status': 'need', 'timestamp': 1336165584, 'need': ('username', 'password'), 'type': 'PASSWORD', 'auth_type': 'Dynamic'}]
2012-05-04 17:06:26-0400 [-] Checking for service profiles
2012-05-04 17:06:29-0400 [HTTPChannel,9,127.0.0.1] *** API CALL f=xmlrpc_SubmitCreds args=['sess_myvpnhost_dyndns_org_dynamic_p7364_CqOcyZPLgABsk9oz_1', {'username': 'myvpnuser', 'password': '[redacted]'}, 'Dynamic', True] kw={} ret=None
2012-05-04 17:06:29-0400 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 57556
2012-05-04 17:06:29-0400 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x017C0230>
2012-05-04 17:06:29-0400 [-] (Port 57556 Closed)
2012-05-04 17:06:29-0400 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x017C0230>
2012-05-04 17:06:30-0400 [XMLProxyQueryProtocol,client] ProfileSignatureVerify.verify: <depth=1 err=X509_V_ERR_SELF_SIGNED_CERT_IN_CHAIN: self signed certificate in certificate chain subj=<X509Name object '/CN=OpenVPN Web CA 2012.04.04 22:23:54 PDT myvpnuser'>>: client/profsig:14,pki/sign:228 (pyovpn.pki.sign.CertVerifyFailed)
2012-05-04 17:06:30-0400 [XMLProxyQueryProtocol,client] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_spskQTcqfXzvnJ5S_2', 10] kw={} ret=[{'timestamp': 1336165590, 'info_type': 'DYNAMIC_SUCCEED', 'type': 'INFO', 'severity': 'info', 'value': 'dynamic profile access succeeded'}]
2012-05-04 17:06:30-0400 [-] vpn_start: JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]: client/cliset:449,internet/defer:746,client/jsondialog:47,client/jsondialog:41,win32serviceutil:806,capiws:57,internet/base:1166,internet/base:1175,internet/base:779,internet/_pollingfile:79,internet/_dumbwin32proc:52,internet/_baseprocess:48,internet/_dumbwin32proc:315,internet/_baseprocess:60,svc/pp:116,svc/svcnotify:25,internet/defer:238,internet/defer:307,internet/defer:323,internet/defer:766,internet/defer:746,client/jsondialog:41,util/error:60,util/error:43 (RUN_ERROR)
2012-05-04 17:06:30-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_spskQTcqfXzvnJ5S_2', 10] kw={} ret=[{'timestamp': 1336165590, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}]
2012-05-04 17:06:30-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_l3rbieeXCvfGncDE_1', 10] kw={} ret=[{'timestamp': 1336165590, 'state': 'disconnect', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:06:30-0400 [HTTPChannel,12,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_spskQTcqfXzvnJ5S_2', 10] kw={} ret=[{'timestamp': 1336165590, 'type': 'DELETE_PENDING'}]
2012-05-04 17:06:30-0400 [HTTPChannel,13,127.0.0.1] *** API CALL f=xmlrpc_EnumProfiles args=[] kw={} ret=[{'hash': '0b3f0f8f72bc72bdb010b46b53be9ca16cb5fd860fecbd44f3f2384d89497caa', 'access_allowed': True, 'global': True, 'host': 'myvpnhost.dyndns.org', 'snapshot': {'info': {'timestamp': 1336165590, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}, 'delete_pending': True}, 'org': 'myvpnhost.local', 'owner': u'jamesl', 'hosts': 'myvpnhost.dyndns.org', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'name': 'myvpnhost.dyndns.org/Dynamic'}]
2012-05-04 17:07:30-0400 [HTTPChannel,20,127.0.0.1] *** API CALL f=xmlrpc_EnumProfiles args=[] kw={} ret=[{'hash': '0b3f0f8f72bc72bdb010b46b53be9ca16cb5fd860fecbd44f3f2384d89497caa', 'access_allowed': True, 'global': True, 'host': 'myvpnhost.dyndns.org', 'snapshot': {'info': {'timestamp': 1336165590, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}, 'delete_pending': True}, 'org': 'myvpnhost.local', 'owner': u'jamesl', 'hosts': 'myvpnhost.dyndns.org', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'name': 'myvpnhost.dyndns.org/Dynamic'}]
2012-05-04 17:07:30-0400 [HTTPChannel,22,127.0.0.1] *** API CALL f=xmlrpc_DisconnectAll args=[] kw={} ret=[(True, None)]
2012-05-04 17:07:33-0400 [HTTPChannel,23,127.0.0.1] *** API CALL f=xmlrpc_GetPreferences args=[] kw={} ret={'proxy_auto': True, 'exec_admin_domain': '', 'update_base_url': 'http://swupdate.openvpn.net/updates', 'log_append': False, 'enable_xd_proxy': True, 'basic_client': True, 'auth_allow_cache_pw': True, 'restrict_domain': '*', 'proxy_auth_allow_basic': True, 'proto_force': '', 'allow_ssl_v2': False, 'connect_timeout': 60, 'implicit_elevation': False, 'exec_user_domain': '*', 'universal_sessions_are_global': False, 'verb': '', 'proxy_auth_allow_save_pw': True, 'user_may_trust_cert': True, 'silent_update': False, 'route_nopull': False, 'enable_connect': True, 'notify_update': True, 'user_hostspec': '*', 'allow_web_import': True}
2012-05-04 17:07:33-0400 [HTTPChannel,24,127.0.0.1] *** API CALL f=xmlrpc_TrackActiveProfiles args=[True] kw={} ret='sess_TrackActiveProfiles_Lfh5z5OoYY6oMQdM_2'
2012-05-04 17:07:33-0400 [HTTPChannel,25,127.0.0.1] *** API CALL f=xmlrpc_UpdateStatus args=[] kw={} ret={}
2012-05-04 17:07:33-0400 [HTTPChannel,26,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_Lfh5z5OoYY6oMQdM_2', 10] kw={} ret=[{'timestamp': 1336165653, 'state': 'add_profile', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:07:33-0400 [HTTPChannel,27,127.0.0.1] *** API CALL f=xmlrpc_ProfileProperties args=['myvpnhost_dyndns_org_dynamic_p7364'] kw={} ret={'hash': '93d6e22cdf691a8c466ffbb2af66ed0f33ce334110d01c5fad7f84df34b6489b', 'name': 'myvpnhost.dyndns.org/Dynamic', 'global': True, 'host': 'myvpnhost.dyndns.org', 'owner': u'jamesl', 'org': 'myvpnhost.local', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'access_allowed': True}
2012-05-04 17:07:44-0400 [HTTPChannel,29,127.0.0.1] *** API CALL f=xmlrpc_Connect args=[{'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'dynamic', 'non_interactive': False}, ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT'], {}] kw={} ret='sess_myvpnhost_dyndns_org_dynamic_p7364_iqpaCRR3rK1R2kw2_1'
2012-05-04 17:07:44-0400 [HTTPChannel,30,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_Lfh5z5OoYY6oMQdM_2', 10] kw={} ret=[{'timestamp': 1336165664, 'state': 'connect', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:07:44-0400 [HTTPChannel,31,127.0.0.1] *** API CALL f=xmlrpc_ConnectActive args=['myvpnhost_dyndns_org_dynamic_p7364', ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT'], 'pending'] kw={} ret='sess_myvpnhost_dyndns_org_dynamic_p7364_f1IHA3m298lp38j1_2'
2012-05-04 17:07:44-0400 [HTTPChannel,32,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_f1IHA3m298lp38j1_2', 10] kw={} ret=[{'status': 'need', 'timestamp': 1336165664, 'need': ('username', 'password'), 'type': 'PASSWORD', 'auth_type': 'Dynamic'}]
2012-05-04 17:07:49-0400 [HTTPChannel,34,127.0.0.1] *** API CALL f=xmlrpc_SubmitCreds args=['sess_myvpnhost_dyndns_org_dynamic_p7364_iqpaCRR3rK1R2kw2_1', {'username': 'myvpnuser', 'password': '[redacted]'}, 'Dynamic', True] kw={} ret=None
2012-05-04 17:07:49-0400 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 21526
2012-05-04 17:07:49-0400 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x017D23B0>
2012-05-04 17:07:49-0400 [-] (Port 21526 Closed)
2012-05-04 17:07:49-0400 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x017D23B0>
2012-05-04 17:07:49-0400 [XMLProxyQueryProtocol,client] ProfileSignatureVerify.verify: <depth=1 err=X509_V_ERR_SELF_SIGNED_CERT_IN_CHAIN: self signed certificate in certificate chain subj=<X509Name object '/CN=OpenVPN Web CA 2012.04.04 22:23:54 PDT myvpnuser'>>: client/profsig:14,pki/sign:228 (pyovpn.pki.sign.CertVerifyFailed)
2012-05-04 17:07:49-0400 [XMLProxyQueryProtocol,client] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_f1IHA3m298lp38j1_2', 10] kw={} ret=[{'timestamp': 1336165669, 'info_type': 'DYNAMIC_SUCCEED', 'type': 'INFO', 'severity': 'info', 'value': 'dynamic profile access succeeded'}]
2012-05-04 17:07:49-0400 [-] vpn_start: JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]: client/cliset:449,internet/defer:746,client/jsondialog:47,client/jsondialog:41,win32serviceutil:806,capiws:57,internet/base:1166,internet/base:1175,internet/base:779,internet/_pollingfile:79,internet/_dumbwin32proc:52,internet/_baseprocess:48,internet/_dumbwin32proc:315,internet/_baseprocess:60,svc/pp:116,svc/svcnotify:25,internet/defer:238,internet/defer:307,internet/defer:323,internet/defer:766,internet/defer:746,client/jsondialog:41,util/error:60,util/error:43 (RUN_ERROR)
2012-05-04 17:07:49-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_f1IHA3m298lp38j1_2', 10] kw={} ret=[{'timestamp': 1336165669, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}]
2012-05-04 17:07:49-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_Lfh5z5OoYY6oMQdM_2', 10] kw={} ret=[{'timestamp': 1336165669, 'state': 'disconnect', 'profile_id': 'myvpnhost_dyndns_org_dynamic_p7364', 'type': 'PROFILE'}]
2012-05-04 17:07:49-0400 [HTTPChannel,37,127.0.0.1] *** API CALL f=xmlrpc_Poll args=['sess_myvpnhost_dyndns_org_dynamic_p7364_f1IHA3m298lp38j1_2', 10] kw={} ret=[{'timestamp': 1336165669, 'type': 'DELETE_PENDING'}]
2012-05-04 17:07:49-0400 [HTTPChannel,38,127.0.0.1] *** API CALL f=xmlrpc_EnumProfiles args=[] kw={} ret=[{'hash': '0b3f0f8f72bc72bdb010b46b53be9ca16cb5fd860fecbd44f3f2384d89497caa', 'access_allowed': True, 'global': True, 'host': 'myvpnhost.dyndns.org', 'snapshot': {'info': {'timestamp': 1336165669, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}, 'delete_pending': True}, 'org': 'myvpnhost.local', 'owner': u'jamesl', 'hosts': 'myvpnhost.dyndns.org', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'name': 'myvpnhost.dyndns.org/Dynamic'}]
2012-05-04 17:08:21-0400 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 4816
2012-05-04 17:08:21-0400 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x01928D90>
2012-05-04 17:08:21-0400 [-] (Port 4816 Closed)
2012-05-04 17:08:21-0400 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x01928D90>
2012-05-04 17:08:21-0400 [MyHTTPPageGetter,client] SoftwareUpdate: Update query error on http://swupdate.openvpn.net/updates/1.8.3/MSI.txt: HTTP GET returned status 404 (HTTP404)
2012-05-04 17:08:21-0400 [MyHTTPPageGetter,client] Schedule swupdate monitor in 4052 seconds, range=(120,14400), error=False, initial=False
2012-05-04 17:09:58-0400 [HTTPChannel,52,127.0.0.1] *** API CALL f=xmlrpc_EnumProfiles args=[] kw={} ret=[{'hash': '0b3f0f8f72bc72bdb010b46b53be9ca16cb5fd860fecbd44f3f2384d89497caa', 'access_allowed': True, 'global': True, 'host': 'myvpnhost.dyndns.org', 'snapshot': {'info': {'timestamp': 1336165669, 'info_type': 'RUN_ERROR', 'type': 'INFO', 'severity': 'error', 'value': 'JSONDialog: Error running jsondialog, status=(1, [], []), stdout=[], stderr=[]'}, 'delete_pending': True}, 'org': 'myvpnhost.local', 'owner': u'jamesl', 'hosts': 'myvpnhost.dyndns.org', 'type': ['dynamic'], 'id': 'myvpnhost_dyndns_org_dynamic_p7364', 'name': 'myvpnhost.dyndns.org/Dynamic'}]
2012-05-04 17:09:58-0400 [HTTPChannel,53,127.0.0.1] *** API CALL f=xmlrpc_DisconnectAll args=[] kw={} ret=[(True, None)]