In version SFOS 18.0.3 MR-3 we would like to change the SSL-port from 8443 to 443.In the dialogue "VPN / Show VPN settings" the value can be changed, but after pressing "Apply" and leaving the dialogue with "close vpn settings" and opening it again with "VPN / Show VPN settings" these settings are lost.
This now also occurs after a downgrade to version 17.5.
Hi Kay Werrmann,
Thank you for reaching out to the Community!
I'm able to change the SSL VPN port to 443 on my XG firewall that is also running on firmware SFOS 18.0.3 MR-3.
Do you have any other local service that is using port 443?
Could you please replicate the issue and collect the following logs from your firewall.
SSH into the XG firewall by following this KBA: Sophos XG Firewall: How to SSH to the firewall using PuTTY utility
Run the following command to collect applog: tail -f /log/applog.log
You also need to put the CSC service in debugging and collect csc logs.
Run the following command to put the csc service in debug: csc custom debug
Note: Run the same command to remove the service from debugging.
Run the following command to collect csc logs: tail -f /log/csc.log
Thanks,
1. tail -f /log/applog.log
XG135_XN03_SFOS 18.0.3 MR-3# tail -f /log/applog.log
Dec 14 09:20:10 apiInterface:entityjson::::::::system::systemgraph=HASH(0xb1f019 0)
Dec 14 09:20:10 Info:: Transaction will not be rolled back for opcode garner:get _xml. If any operation fails, request is part of multiple request :
Dec 14 09:20:10
-->garner: get_xml
Dec 14 09:20:10
sizeof sg=0, sizeof st=0, sizeof ss=0
Dec 14 09:20:10
Graph[0]= ssl_curr_summary , time[0]= hourly , Substrs[0]=N/A
Dec 14 09:20:10
->input_string=ssl_curr_summary,hourly,N/A
Dec 14 09:21:11 Request type = 1
Dec 14 09:21:11 apiInterface:versionsupported: true.
Dec 14 09:21:11 apiInterface:request mode -> 205.
Dec 14 09:21:11 apiInterface:Current ver :::'1800.2'
Dec 14 09:21:11 apiInterface:entityjson::::::::vpn::sslvpntunnel=HASH(0xb1f9c10)
Dec 14 09:21:11 Info:: Transaction will not be rolled back for opcode sslvpn_glo bal_settings. If any operation fails, request is part of multiple request :
Dec 14 09:21:39 Request type = 1
Dec 14 09:21:39 apiInterface:versionsupported: true.
Dec 14 09:21:39 apiInterface:request mode -> 205.
Dec 14 09:21:39 apiInterface:Current ver :::'1800.2'
Dec 14 09:21:39 apiInterface:entityjson::::::::vpn::sslvpntunnel=HASH(0xb1f9c10)
Dec 14 09:21:39 Info:: Transaction will not be rolled back for opcode sslvpn_global_settings. If any operation fails, request is part of multiple request :
^C
XG135_XN03_SFOS 18.0.3 MR-3#
----------------------------------------------------------------------------
2. csc custom debug -> tail -f /log/csc.log
XG135_XN03_SFOS 18.0.3 MR-3# csc custom debug
XG135_XN03_SFOS 18.0.3 MR-3# tail -f /log/csc.log
DEBUG Dec 14 09:30:13 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16929
DEBUG Dec 14 09:30:13 [listener:1654]: Received response from worker
DEBUG Dec 14 09:30:13 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 184 bytes to requester
DEBUG Dec 14 09:30:13 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:30:13 [listener:1654]: Worker with pid 16929 got executed, will revive again.
DEBUG Dec 14 09:30:13 [listener:1654]: Worker 16929 is removed from busy list
DEBUG Dec 14 09:30:13 [listener:1654]: csc_waitpid: Process with pid 16929, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:13 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 214200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:13 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:13 [listener:1654]: Realising worker 16935
DEBUG Dec 14 09:30:26 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 45 bytes are read by listener
DEBUG Dec 14 09:30:26 [listener:1654]: register_request_inet: request from port '41368'
INFO Dec 14 09:30:26 [listener:1654]: protocol content type not found
INFO Dec 14 09:30:26 [listener:1654]: protocol length not found
INFO Dec 14 09:30:26 [listener:1654]: Assigning free worker 16935
DEBUG Dec 14 09:30:26 [listener:1654]: assign_to_busy_queue: assigning worker 16935
DEBUG Dec 14 09:30:26 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 16935
DEBUG Dec 14 09:30:26 [worker:16935]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:30:26 [worker:16935]: # OPCODE Called: 'u2d_pt_installer'
MESSAGE Dec 14 09:30:26 [worker:16935]: {"request":{"method":"nopcode","name":"u2d_pt_installer","version":"1.10","type":"text","length":0}}
DEBUG Dec 14 09:30:26 [worker:16935]: Main TLV:{ 1, data:{ 2, 4, 274200} , 9}
DEBUG Dec 14 09:30:26 [worker:16935]: recv_dbtlv_data: tlv->type(1) : 1693501
DEBUG Dec 14 09:30:26 [worker:16935]: worker_proc: dbhandle init for 16935(1,1693501)
DEBUG Dec 14 09:30:26 [worker:16935]: ### insert_uuid: hdr: len=0 content=1 method=1 name=u2d_pt_installer
DEBUG Dec 14 09:30:26 [worker:16935]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:26 [worker:16935]: ### insert_uuid: uuid insertion took 0 s 16319 ns
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: TRYLOCK: 38
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: do_get: is_eula
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: csc_execve: Child exited with status 0
DEBUG Dec 14 09:30:26 [u2d_pt_installer:16935]: log_exec: Command: /scripts/u2d/u2d_pt_dload_checker.sh
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: create_act_out_perl_obj: out.status=0
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: create_act_out_perl_obj: TEXT out.output=UPDATE 1
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: UNLOCK: 38
INFO Dec 14 09:30:26 [u2d_pt_installer:16935]: opcode 'u2d_pt_installer': time taken: 0.321954724 seconds
DEBUG Dec 14 09:30:26 [worker:16935]: worker_proc: going to release dbhandle for 16935(1,1693501)
DEBUG Dec 14 09:30:26 [worker:16935]: Main TLV:{ 4, data:{ 1, 4, 3DD7190} data:{ 2, 4, 274200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:30:26 [worker:16935]: {"response":{"method":"nopcode","name":"u2d_pt_installer","version":"1.10","type":"text","length":2,"data":OK,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:26 [worker:16935]: # OPCODE Exited: 'u2d_pt_installer' with Status: '200'
DEBUG Dec 14 09:30:26 [worker:16935]: write_packet: 52+2+2
DEBUG Dec 14 09:30:26 [listener:1654]: read_response_from_sockpair: 56 bytes read from sockpair worker 16935
DEBUG Dec 14 09:30:26 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16935
DEBUG Dec 14 09:30:26 [listener:1654]: Received response from worker
INFO Dec 14 09:30:26 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:30:26 [listener:1654]: Worker with pid 16935 got executed, will revive again.
DEBUG Dec 14 09:30:26 [listener:1654]: Worker 16935 is removed from busy list
DEBUG Dec 14 09:30:26 [listener:1654]: csc_waitpid: Process with pid 16935, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:26 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 274200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:26 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:26 [listener:1654]: Realising worker 16987
DEBUG Dec 14 09:30:27 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 45 bytes are read by listener
DEBUG Dec 14 09:30:27 [listener:1654]: register_request_inet: request from port '33497'
INFO Dec 14 09:30:27 [listener:1654]: protocol content type not found
INFO Dec 14 09:30:27 [listener:1654]: protocol length not found
INFO Dec 14 09:30:27 [listener:1654]: Assigning free worker 16987
DEBUG Dec 14 09:30:27 [listener:1654]: assign_to_busy_queue: assigning worker 16987
DEBUG Dec 14 09:30:27 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 16987
DEBUG Dec 14 09:30:27 [worker:16987]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:30:27 [worker:16987]: # OPCODE Called: 'u2d_dr_installer'
MESSAGE Dec 14 09:30:27 [worker:16987]: {"request":{"method":"nopcode","name":"u2d_dr_installer","version":"1.10","type":"text","length":0}}
DEBUG Dec 14 09:30:27 [worker:16987]: Main TLV:{ 1, data:{ 2, 4, 5B4200} , 9}
DEBUG Dec 14 09:30:27 [worker:16987]: recv_dbtlv_data: tlv->type(1) : 1698701
DEBUG Dec 14 09:30:27 [worker:16987]: worker_proc: dbhandle init for 16987(1,1698701)
DEBUG Dec 14 09:30:27 [worker:16987]: ### insert_uuid: hdr: len=0 content=1 method=1 name=u2d_dr_installer
DEBUG Dec 14 09:30:27 [worker:16987]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:27 [worker:16987]: ### insert_uuid: uuid insertion took 0 s 15898 ns
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: TRYLOCK: 51
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: do_get: g_ha_mode
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: do_get: is_eula
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: csc_execve: Child exited with status 0
DEBUG Dec 14 09:30:27 [u2d_dr_installer:16987]: log_exec: Command: /scripts/u2d/u2d_dr_dload_checker.sh
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: create_act_out_perl_obj: out.status=0
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: UNLOCK: 51
INFO Dec 14 09:30:27 [u2d_dr_installer:16987]: opcode 'u2d_dr_installer': time taken: 0.289672693 seconds
DEBUG Dec 14 09:30:27 [worker:16987]: worker_proc: going to release dbhandle for 16987(1,1698701)
DEBUG Dec 14 09:30:27 [worker:16987]: Main TLV:{ 4, data:{ 1, 4, 8DEB190} data:{ 2, 4, 5B4200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:30:27 [worker:16987]: {"response":{"method":"nopcode","name":"u2d_dr_installer","version":"1.10","type":"text","length":2,"data":OK,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:27 [worker:16987]: # OPCODE Exited: 'u2d_dr_installer' with Status: '200'
DEBUG Dec 14 09:30:27 [worker:16987]: write_packet: 52+2+2
DEBUG Dec 14 09:30:27 [worker:16987]: write_packet: write 56 bytes to listener
DEBUG Dec 14 09:30:27 [listener:1654]: read_response_from_sockpair: 56 bytes read from sockpair worker 16987
DEBUG Dec 14 09:30:27 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16987
DEBUG Dec 14 09:30:27 [listener:1654]: Received response from worker
INFO Dec 14 09:30:27 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:30:27 [listener:1654]: Worker with pid 16987 got executed, will revive again.
DEBUG Dec 14 09:30:27 [listener:1654]: Worker 16987 is removed from busy list
DEBUG Dec 14 09:30:27 [listener:1654]: csc_waitpid: Process with pid 16987, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:27 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 5B4200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:27 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:27 [listener:1654]: Realising worker 16994
DEBUG Dec 14 09:30:32 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 724 bytes are read by listener
DEBUG Dec 14 09:30:32 [listener:1654]: register_request_inet: request from port '53189'
INFO Dec 14 09:30:32 [listener:1654]: protocol dbhandle not found
INFO Dec 14 09:30:32 [listener:1654]: Assigning free worker 16994
DEBUG Dec 14 09:30:32 [listener:1654]: assign_to_busy_queue: assigning worker 16994
DEBUG Dec 14 09:30:32 [listener:1654]: send_data_to_sockpair: listener has send 710 bytes to sockpair worker 16994
DEBUG Dec 14 09:30:32 [worker:16994]: read_packet: read() 710 bytes from listener
DEBUG Dec 14 09:30:32 [worker:16994]: # OPCODE Called: 'apiInterface'
MESSAGE Dec 14 09:30:32 [worker:16994]: {"request":{"method":"opcode","name":"apiInterface","version":"1.8","type":"json","length":658,"data":{"keylifetime":"28800","leaseipmask":"255.255.255.0","___component":"GUI","prefix":"64","leasemode":"1","dpdtimeout":"180","transactionid":"454","idletimeoutfullaccess":"15","mode":205,"protocol":"1","keysize":"2048","APIVersion":"1800.2","servercert":"ApplianceCertificate","___serverip":"172.16.16.16","authalgo":"SHA256","___serverport":4444,"enabledebug":"0","compvpntraffic":"1","leaseipstart":"10.81.234.5","leaseipv6":"2001:db8::1:0","currentlyloggedinuserid":3,"leaseipend":"10.81.234.55","port":"6443","___serverprotocol":"HTTP","___username":"admin","___meta":{"sessionType":1},"currentlyloggedinuserip":"172.16.16.100","encryptalgo":"AES-128-CBC"}}}
DEBUG Dec 14 09:30:32 [worker:16994]: Main TLV:{ 1, data:{ 2, 4, 624200} , 9}
DEBUG Dec 14 09:30:32 [worker:16994]: recv_dbtlv_data: tlv->type(1) : 1699401
DEBUG Dec 14 09:30:32 [worker:16994]: worker_proc: dbhandle init for 16994(1,1699401)
DEBUG Dec 14 09:30:32 [worker:16994]: ### insert_uuid: hdr: len=658 content=0 method=0 name=apiInterface
DEBUG Dec 14 09:30:32 [worker:16994]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
DEBUG Dec 14 09:30:32 [worker:16994]: ### insert_uuid: uuid insertion took 0 s 27535 ns
INFO Dec 14 09:30:33 [apiInterface:16994]: creating json object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL sanitizeRequest
DEBUG Dec 14 09:30:33 [apiInterface:16994]: Initializing database handle
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select case when usertype in (1,7) then 'adminuser' else 'normaluser' end as usertype from tbluser where userid=3'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=curLoggedIn
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: curLoggedIn.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON curLoggedIn.output={ "usertype": [ "adminuser" ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL variableInitialization
INFO Dec 14 09:30:33 [apiInterface:16994]: csc_query: After PQexec, result not NULL
INFO Dec 14 09:30:33 [apiInterface:16994]: csc_query: After PQexec, result2 not NULL
INFO Dec 14 09:30:33 [apiInterface:16994]: csc_query: Txid:8608
INFO Dec 14 09:30:33 [apiInterface:16994]: csc_query: After PQclear
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'start transaction'
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=17
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL isAPIVersionSupported
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=37
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL opcodePreProcess
INFO Dec 14 09:30:33 [apiInterface:16994]: executing FORLOOP
INFO Dec 14 09:30:33 [apiInterface:16994]: FORLOOP condition true
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL checkUserPermission
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select entityid from tblcrevent where mode = 205'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON result.output={ "entityid": [ 26 ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select cmstatus from tblcentralmgmt'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=CMResult
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: CMResult.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON CMResult.output={ "cmstatus": [ 0 ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select roleid from tbluserrolerelation where userid = 3'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON result.output={ "roleid": [ 1 ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select operationallowed from tblacldefinition where roleid = 1 and entityid = 26'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON result.output={ "operationallowed": [ 15 ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL preMigration
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL createModeJSON
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=34
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL migrateToCurrVersion
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=38
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL createJson
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL validateJson
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=65
PAckage ::::vpn::sslvpntunnelINFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL handleDeleteRequest
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL replyIfErrorAtValidation
INFO Dec 14 09:30:33 [apiInterface:16994]: ACTION: CALL getOldObject
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=205'
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: varname=opout
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: opout.status=0
INFO Dec 14 09:30:33 [apiInterface:16994]: create_act_out_perl_obj: JSON opout.output={ "opcode": [ "sslvpn_global_settings" ], "opcodetype": [ "2" ], "perlpackagename": [ "" ] }
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:33 [apiInterface:16994]: logger: applog
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_log_to_file: length=141
DEBUG Dec 14 09:30:33 [apiInterface:16994]: execute_action: DYNACODE variable:opcodename
DEBUG Dec 14 09:30:33 [apiInterface:16994]: execute_action: DYNACODE opcode:sslvpn_global_settings
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_ao: OPCODE sslvpn_global_settings
DEBUG Dec 14 09:30:33 [apiInterface:16994]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:33 [apiInterface:16994]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:33 [apiInterface:16994]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:33 [apiInterface:16994]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:33 [apiInterface:16994]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:33 [apiInterface:16994]: do_ao: OPCODE sslvpn_global_settings CONTENT-TYPE:json, BODY_LEN:910
DEBUG Dec 14 09:30:33 [listener:1654]: ln_recvfrom: fd '109.TCP.INET.auxilary': 1003 bytes are read by listener
DEBUG Dec 14 09:30:33 [listener:1654]: register_request_inet: request from port '0'
INFO Dec 14 09:30:33 [listener:1654]: Assigning free worker 16934
DEBUG Dec 14 09:30:33 [listener:1654]: assign_to_busy_queue: assigning worker 16934
DEBUG Dec 14 09:30:33 [listener:1654]: send_data_to_sockpair: listener has send 962 bytes to sockpair worker 16934
DEBUG Dec 14 09:30:33 [worker:16934]: read_packet: read() 962 bytes from listener
DEBUG Dec 14 09:30:33 [worker:16934]: # OPCODE Called: 'sslvpn_global_settings'
MESSAGE Dec 14 09:30:33 [worker:16934]: {"request":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"json","length":910,"data":{ "transactionid": "454", "leaseipv6": "2001:db8::1:0", "Event": "UPDATE", "___component": "GUI", "leaseipstart": "10.81.234.5", "leaseipend": "10.81.234.55", "___username": "admin", "perusercert": "1", "dpdtimeout": 180, "authalgo": "SHA256", "mode": 205, "secondarydns": "", "servercert": "ApplianceCertificate", "protocol": "1", "users": "", "___meta": { "sessionType": 1 }, "overridehost": "", "prefix": "64", "currentlyloggedinuserid": 3, "primarydns": "", "___serverip": "172.16.16.16", "idletimeoutfullaccess": "15", "compvpntraffic": "1", "keysize": "2048", "___serverprotocol": "HTTP", "Entity": "sslvpntunnel", "port": "6443", "secondarywins": "", "encryptalgo": "AES-128-CBC", "primarywins": "", "domainname": "", "leasemode": "1", "currentlyloggedinuserip": "172.16.16.100", "APIVersion": "1800.2", "leaseipmask": "255.255.255.0", "keylifetime": "28800", "___serverport": 4444, "enabledebug": "0" }}}
DEBUG Dec 14 09:30:33 [worker:16934]: ### insert_uuid: hdr: len=910 content=0 method=0 name=sslvpn_global_settings
DEBUG Dec 14 09:30:33 [worker:16934]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:33 [worker:16934]: ### insert_uuid: uuid insertion took 0 s 16995 ns
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: creating json object
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: json_to_perl: Object
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: json_to_perl: Object
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: Initializing database handle
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: csc_query: After PQexec, result not NULL
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: csc_query: After PQexec, result2 not NULL
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: csc_query: Txid:8609
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: csc_query: After PQclear
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: do_query: Query: 'start transaction'
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: do_query: Query: 'select country from tblrootcainfo where caname='Default''
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: create_act_out_perl_obj: out.status=0
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: create_act_out_perl_obj: JSON out.output={ "country": [ "" ] }
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: json_to_perl: Object
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: json_to_perl: Array
DEBUG Dec 14 09:30:34 [sslvpn_global_settings:16934]: do_query: Query: 'rollback'
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: opcode 'sslvpn_global_settings': time taken: 0.283496160 seconds
DEBUG Dec 14 09:30:34 [worker:16934]: {"response":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"text","length":104,"data":{ "statusmessage": "Default CA is not configured", "invalidparams": [ "perusercert" ], "status": "501" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:34 [worker:16934]: # OPCODE Exited: 'sslvpn_global_settings' with Status: '500'
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: 52+104+2
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: write 158 bytes to listener
DEBUG Dec 14 09:30:34 [listener:1654]: read_response_from_sockpair: 158 bytes read from sockpair worker 16934
DEBUG Dec 14 09:30:34 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16934
DEBUG Dec 14 09:30:34 [listener:1654]: Received response from worker
DEBUG Dec 14 09:30:34 [listener:1654]: ln_sendto: fd '109.TCP.INET.auxilary' has sent 140 bytes to requester
DEBUG Dec 14 09:30:34 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:30:34 [listener:1654]: Worker with pid 16934 got executed, will revive again.
DEBUG Dec 14 09:30:34 [listener:1654]: Worker 16934 is removed from busy list
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: out.status=500
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: TEXT out.output={ "statusmessage": "Default CA is not configured", "invalidparams": [ "perusercert" ], "status": "501" }
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: out.error=OK
DEBUG Dec 14 09:30:34 [apiInterface:16994]: do_query: Query: 'rollback'
INFO Dec 14 09:30:34 [apiInterface:16994]: ACTION: CALL replyFailureMessage
DEBUG Dec 14 09:30:34 [listener:1654]: csc_waitpid: Process with pid 16934, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:34 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 264200} data:{ 5, 4, 1000} INFO Dec 14 09:30:34 [apiInterface:16994]: ACTION: DLOPEN(json2hash, response)
, 27}
DEBUG Dec 14 09:30:34 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:34 [apiInterface:16994]: json_to_perl: Array
DEBUG Dec 14 09:30:34 [listener:1654]: csc_socketpair called: biggest fd is 110
INFO Dec 14 09:30:34 [apiInterface:16994]: ACTION: CALL opcodeCCCFailLog
DEBUG Dec 14 09:30:34 [listener:1654]: Realising worker 17003
DEBUG Dec 14 09:30:34 [listener:1654]: release_fd_struct: fd '109.TCP.INET.auxilary' is closed
DEBUG Dec 14 09:30:34 [apiInterface:16994]: do_query: Query: 'select servicevalue from tblclientservices where servicekey='CCCEnabled''
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: varname=cccEnable
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: cccEnable.status=0
INFO Dec 14 09:30:34 [apiInterface:16994]: create_act_out_perl_obj: JSON cccEnable.output={ "servicevalue": [ "no" ] }
DEBUG Dec 14 09:30:34 [apiInterface:16994]: json_to_perl: Object
DEBUG Dec 14 09:30:34 [apiInterface:16994]: json_to_perl: Array
INFO Dec 14 09:30:34 [apiInterface:16994]: opcode 'apiInterface': time taken: 1.084961800 seconds
DEBUG Dec 14 09:30:34 [worker:16994]: worker_proc: going to release dbhandle for 16994(1,1699401)
DEBUG Dec 14 09:30:34 [worker:16994]: Main TLV:{ 4, data:{ 1, 4, 49EE190} data:{ 2, 4, 624200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:30:34 [worker:16994]: {"response":{"method":"opcode","name":"apiInterface","version":"1.8","type":"text","length":149,"data":{ "statusmessage": "Default CA is not configured", "Entity": "sslvpntunnel", "invalidparams": [ "perusercert" ], "Event": "UPDATE", "status": "501" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:34 [worker:16994]: # OPCODE Exited: 'apiInterface' with Status: '500'
DEBUG Dec 14 09:30:34 [worker:16994]: write_packet: 52+149+2
DEBUG Dec 14 09:30:34 [listener:1654]: read_response_from_sockpair: 203 bytes read from sockpair worker 16994
DEBUG Dec 14 09:30:34 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16994
DEBUG Dec 14 09:30:34 [listener:1654]: Received response from worker
DEBUG Dec 14 09:30:34 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 184 bytes to requester
DEBUG Dec 14 09:30:34 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:30:34 [listener:1654]: Worker with pid 16994 got executed, will revive again.
DEBUG Dec 14 09:30:34 [listener:1654]: Worker 16994 is removed from busy list
DEBUG Dec 14 09:30:34 [listener:1654]: csc_waitpid: Process with pid 16994, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:34 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 624200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:34 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:34 [listener:1654]: Realising worker 17004
DEBUG Dec 14 09:30:43 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 52 bytes are read by listener
DEBUG Dec 14 09:30:43 [listener:1654]: register_request_inet: request from port '37580'
INFO Dec 14 09:30:43 [listener:1654]: protocol content type not found
INFO Dec 14 09:30:43 [listener:1654]: protocol length not found
INFO Dec 14 09:30:43 [listener:1654]: Assigning free worker 17004
DEBUG Dec 14 09:30:43 [listener:1654]: assign_to_busy_queue: assigning worker 17004
DEBUG Dec 14 09:30:43 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 17004
DEBUG Dec 14 09:30:43 [worker:17004]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:30:43 [worker:17004]: # OPCODE Called: 'smtp_quarantine_cleanup'
MESSAGE Dec 14 09:30:43 [worker:17004]: {"request":{"method":"nopcode","name":"smtp_quarantine_cleanup","version":"1.8","type":"text","length":0}}
DEBUG Dec 14 09:30:43 [worker:17004]: Main TLV:{ 1, data:{ 2, 4, 6C4200} , 9}
DEBUG Dec 14 09:30:43 [worker:17004]: recv_dbtlv_data: tlv->type(1) : 1700401
DEBUG Dec 14 09:30:43 [worker:17004]: worker_proc: dbhandle init for 17004(1,1700401)
DEBUG Dec 14 09:30:43 [worker:17004]: ### insert_uuid: hdr: len=0 content=1 method=1 name=smtp_quarantine_cleanup
DEBUG Dec 14 09:30:43 [worker:17004]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:43 [worker:17004]: ### insert_uuid: uuid insertion took 0 s 16401 ns
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: ACTION: DLOPEN(iviewdb_query, delete_que_tmp)
DEBUG Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: init_dbase_handle: handle for (dbname=iviewdb user=nobody port=5433)
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: create_act_out_perl_obj: varname=del_que
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: create_act_out_perl_obj: del_que.status=0
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: create_act_out_perl_obj: JSON del_que.output={ "quarantinearea_path": [ ] }
DEBUG Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: json_to_perl: Object
DEBUG Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: json_to_perl: Array
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: executing FORLOOP
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: FORLOOP condition false
DEBUG Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: Initializing database handle
DEBUG Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: do_query: Query: 'commit'
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: do_at: (smtp_que_cl_5M:add)
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: do_at: ATTRIBUTE(minutes 1) OPCODE(smtp_quarantine_cleanup)
DEBUG Dec 14 09:30:43 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 116 bytes are read by listener
DEBUG Dec 14 09:30:43 [listener:1654]: register_request_inet: request from port '38920'
INFO Dec 14 09:30:43 [listener:1654]: protocol content type not found
DEBUG Dec 14 09:30:43 [listener:1654]: send_data_to_sockpair: listener has send 104 bytes to
DEBUG Dec 14 09:30:43 [listener:1654]: read_response_from_sockpair: 54 bytes read from
DEBUG Dec 14 09:30:43 [listener:1654]: is_response_complete: Complete response is received from
DEBUG Dec 14 09:30:43 [listener:1654]: Received response from worker
INFO Dec 14 09:30:43 [listener:1654]: send_buffer_to_requester: Not sending response to requester
INFO Dec 14 09:30:43 [smtp_quarantine_cleanup:17004]: opcode 'smtp_quarantine_cleanup': time taken: 0.284362647 seconds
DEBUG Dec 14 09:30:43 [worker:17004]: worker_proc: going to release dbhandle for 17004(1,1700401)
DEBUG Dec 14 09:30:43 [worker:17004]: Main TLV:{ 4, data:{ 1, 4, 31F2190} data:{ 2, 4, 6C4200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:30:43 [worker:17004]: {"response":{"method":"nopcode","name":"smtp_quarantine_cleanup","version":"1.8","type":"text","length":47,"data":{ "statusmessage": "success", "status": "200" },"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:43 [worker:17004]: # OPCODE Exited: 'smtp_quarantine_cleanup' with Status: '200'
DEBUG Dec 14 09:30:43 [worker:17004]: write_packet: 52+47+2
DEBUG Dec 14 09:30:43 [worker:17004]: write_packet: write 101 bytes to listener
DEBUG Dec 14 09:30:43 [listener:1654]: read_response_from_sockpair: 101 bytes read from sockpair worker 17004
DEBUG Dec 14 09:30:43 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17004
DEBUG Dec 14 09:30:43 [listener:1654]: Received response from worker
INFO Dec 14 09:30:43 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:30:43 [listener:1654]: Worker with pid 17004 got executed, will revive again.
DEBUG Dec 14 09:30:43 [listener:1654]: Worker 17004 is removed from busy list
DEBUG Dec 14 09:30:43 [listener:1654]: csc_waitpid: Process with pid 17004, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:43 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 6C4200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:43 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:43 [listener:1654]: Realising worker 17009
DEBUG Dec 14 09:30:48 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 723 bytes are read by listener
DEBUG Dec 14 09:30:48 [listener:1654]: register_request_inet: request from port '35168'
INFO Dec 14 09:30:48 [listener:1654]: protocol dbhandle not found
INFO Dec 14 09:30:48 [listener:1654]: Assigning free worker 17009
DEBUG Dec 14 09:30:48 [listener:1654]: assign_to_busy_queue: assigning worker 17009
DEBUG Dec 14 09:30:48 [listener:1654]: send_data_to_sockpair: listener has send 709 bytes to sockpair worker 17009
DEBUG Dec 14 09:30:48 [worker:17009]: read_packet: read() 709 bytes from listener
DEBUG Dec 14 09:30:48 [worker:17009]: # OPCODE Called: 'apiInterface'
MESSAGE Dec 14 09:30:48 [worker:17009]: {"request":{"method":"opcode","name":"apiInterface","version":"1.8","type":"json","length":657,"data":{"keylifetime":"28800","leaseipmask":"255.255.255.0","___component":"GUI","prefix":"64","leasemode":"1","dpdtimeout":"180","transactionid":"455","idletimeoutfullaccess":"15","mode":205,"protocol":"1","keysize":"2048","APIVersion":"1800.2","servercert":"ApplianceCertificate","___serverip":"172.16.16.16","authalgo":"SHA256","___serverport":4444,"enabledebug":"0","compvpntraffic":"1","leaseipstart":"10.81.234.5","leaseipv6":"2001:db8::1:0","currentlyloggedinuserid":3,"leaseipend":"10.81.234.55","port":"443","___serverprotocol":"HTTP","___username":"admin","___meta":{"sessionType":1},"currentlyloggedinuserip":"172.16.16.100","encryptalgo":"AES-128-CBC"}}}
DEBUG Dec 14 09:30:48 [worker:17009]: Main TLV:{ 1, data:{ 2, 4, 714200} , 9}
DEBUG Dec 14 09:30:48 [worker:17009]: recv_dbtlv_data: tlv->type(1) : 1700901
DEBUG Dec 14 09:30:48 [worker:17009]: worker_proc: dbhandle init for 17009(1,1700901)
DEBUG Dec 14 09:30:48 [worker:17009]: ### insert_uuid: hdr: len=657 content=0 method=0 name=apiInterface
DEBUG Dec 14 09:30:48 [worker:17009]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
DEBUG Dec 14 09:30:48 [worker:17009]: ### insert_uuid: uuid insertion took 0 s 27589 ns
INFO Dec 14 09:30:48 [apiInterface:17009]: creating json object
DEBUG Dec 14 09:30:48 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:48 [apiInterface:17009]: json_to_perl: Object
INFO Dec 14 09:30:48 [apiInterface:17009]: ACTION: CALL sanitizeRequest
DEBUG Dec 14 09:30:48 [apiInterface:17009]: Initializing database handle
DEBUG Dec 14 09:30:48 [apiInterface:17009]: do_query: Query: 'select case when usertype in (1,7) then 'adminuser' else 'normaluser' end as usertype from tbluser where userid=3'
INFO Dec 14 09:30:48 [apiInterface:17009]: create_act_out_perl_obj: varname=curLoggedIn
INFO Dec 14 09:30:48 [apiInterface:17009]: create_act_out_perl_obj: curLoggedIn.status=0
INFO Dec 14 09:30:48 [apiInterface:17009]: create_act_out_perl_obj: JSON curLoggedIn.output={ "usertype": [ "adminuser" ] }
DEBUG Dec 14 09:30:48 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:48 [apiInterface:17009]: json_to_perl: Array
INFO Dec 14 09:30:48 [apiInterface:17009]: ACTION: CALL variableInitialization
INFO Dec 14 09:30:49 [apiInterface:17009]: csc_query: After PQexec, result not NULL
INFO Dec 14 09:30:49 [apiInterface:17009]: csc_query: After PQexec, result2 not NULL
INFO Dec 14 09:30:49 [apiInterface:17009]: csc_query: Txid:8613
INFO Dec 14 09:30:49 [apiInterface:17009]: csc_query: After PQclear
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'start transaction'
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=17
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL isAPIVersionSupported
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=37
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL opcodePreProcess
INFO Dec 14 09:30:49 [apiInterface:17009]: executing FORLOOP
INFO Dec 14 09:30:49 [apiInterface:17009]: FORLOOP condition true
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL checkUserPermission
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select entityid from tblcrevent where mode = 205'
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON result.output={ "entityid": [ 26 ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select cmstatus from tblcentralmgmt'
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=CMResult
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: CMResult.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON CMResult.output={ "cmstatus": [ 0 ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select roleid from tbluserrolerelation where userid = 3'
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON result.output={ "roleid": [ 1 ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select operationallowed from tblacldefinition where roleid = 1 and entityid = 26'
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=result
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: result.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON result.output={ "operationallowed": [ 15 ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL preMigration
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL createModeJSON
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=34
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL migrateToCurrVersion
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=38
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL createJson
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL validateJson
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=65
PAckage ::::vpn::sslvpntunnelINFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL handleDeleteRequest
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL replyIfErrorAtValidation
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL getOldObject
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=205'
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=opout
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: opout.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON opout.output={ "opcode": [ "sslvpn_global_settings" ], "opcodetype": [ "2" ], "perlpackagename": [ "" ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [apiInterface:17009]: logger: applog
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_log_to_file: length=141
DEBUG Dec 14 09:30:49 [apiInterface:17009]: execute_action: DYNACODE variable:opcodename
DEBUG Dec 14 09:30:49 [apiInterface:17009]: execute_action: DYNACODE opcode:sslvpn_global_settings
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_ao: OPCODE sslvpn_global_settings
DEBUG Dec 14 09:30:49 [apiInterface:17009]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:49 [apiInterface:17009]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:49 [apiInterface:17009]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:49 [apiInterface:17009]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:49 [apiInterface:17009]: perl_to_json: FLAG_SET: INTEGER! Returning integer type!
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_ao: OPCODE sslvpn_global_settings CONTENT-TYPE:json, BODY_LEN:909
DEBUG Dec 14 09:30:49 [listener:1654]: ln_recvfrom: fd '109.TCP.INET.auxilary': 1002 bytes are read by listener
DEBUG Dec 14 09:30:49 [listener:1654]: register_request_inet: request from port '0'
INFO Dec 14 09:30:49 [listener:1654]: Assigning free worker 17003
DEBUG Dec 14 09:30:49 [listener:1654]: assign_to_busy_queue: assigning worker 17003
DEBUG Dec 14 09:30:49 [listener:1654]: send_data_to_sockpair: listener has send 961 bytes to sockpair worker 17003
DEBUG Dec 14 09:30:49 [worker:17003]: read_packet: read() 961 bytes from listener
DEBUG Dec 14 09:30:49 [worker:17003]: # OPCODE Called: 'sslvpn_global_settings'
MESSAGE Dec 14 09:30:49 [worker:17003]: {"request":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"json","length":909,"data":{ "leaseipstart": "10.81.234.5", "keysize": "2048", "overridehost": "", "servercert": "ApplianceCertificate", "enabledebug": "0", "Entity": "sslvpntunnel", "mode": 205, "APIVersion": "1800.2", "Event": "UPDATE", "___meta": { "sessionType": 1 }, "port": "443", "___serverport": 4444, "secondarydns": "", "leaseipmask": "255.255.255.0", "transactionid": "455", "authalgo": "SHA256", "keylifetime": "28800", "currentlyloggedinuserip": "172.16.16.100", "compvpntraffic": "1", "protocol": "1", "leasemode": "1", "___component": "GUI", "primarywins": "", "primarydns": "", "domainname": "", "prefix": "64", "encryptalgo": "AES-128-CBC", "idletimeoutfullaccess": "15", "leaseipv6": "2001:db8::1:0", "___serverprotocol": "HTTP", "perusercert": "1", "dpdtimeout": 180, "currentlyloggedinuserid": 3, "___serverip": "172.16.16.16", "secondarywins": "", "leaseipend": "10.81.234.55", "users": "", "___username": "admin" }}}
DEBUG Dec 14 09:30:49 [worker:17003]: ### insert_uuid: hdr: len=909 content=0 method=0 name=sslvpn_global_settings
DEBUG Dec 14 09:30:49 [worker:17003]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:49 [worker:17003]: ### insert_uuid: uuid insertion took 0 s 17326 ns
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: creating json object
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: Initializing database handle
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: csc_query: After PQexec, result not NULL
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: csc_query: After PQexec, result2 not NULL
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: csc_query: Txid:8614
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: csc_query: After PQclear
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: do_query: Query: 'start transaction'
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: do_query: Query: 'select country from tblrootcainfo where caname='Default''
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: create_act_out_perl_obj: out.status=0
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: create_act_out_perl_obj: JSON out.output={ "country": [ "" ] }
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [sslvpn_global_settings:17003]: do_query: Query: 'rollback'
INFO Dec 14 09:30:49 [sslvpn_global_settings:17003]: opcode 'sslvpn_global_settings': time taken: 0.285421462 seconds
DEBUG Dec 14 09:30:49 [worker:17003]: {"response":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"text","length":104,"data":{ "status": "501", "invalidparams": [ "perusercert" ], "statusmessage": "Default CA is not configured" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:49 [worker:17003]: # OPCODE Exited: 'sslvpn_global_settings' with Status: '500'
DEBUG Dec 14 09:30:49 [worker:17003]: write_packet: 52+104+2
DEBUG Dec 14 09:30:49 [worker:17003]: write_packet: write 158 bytes to listener
DEBUG Dec 14 09:30:49 [listener:1654]: read_response_from_sockpair: 158 bytes read from sockpair worker 17003
DEBUG Dec 14 09:30:49 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17003
DEBUG Dec 14 09:30:49 [listener:1654]: Received response from worker
DEBUG Dec 14 09:30:49 [listener:1654]: ln_sendto: fd '109.TCP.INET.auxilary' has sent 140 bytes to requester
DEBUG Dec 14 09:30:49 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:30:49 [listener:1654]: Worker with pid 17003 got executed, will revive again.
DEBUG Dec 14 09:30:49 [listener:1654]: Worker 17003 is removed from busy list
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=out
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: out.status=500
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: TEXT out.output={ "status": "501", "invalidparams": [ "perusercert" ], "statusmessage": "Default CA is not configured" }
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: out.error=OK
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'rollback'
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL replyFailureMessage
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: DLOPEN(json2hash, response)
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
DEBUG Dec 14 09:30:49 [listener:1654]: csc_waitpid: Process with pid 17003, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:49 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 6B4200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:49 [listener:1654]: csc_socketpair called: biggest fd is 110
INFO Dec 14 09:30:49 [apiInterface:17009]: ACTION: CALL opcodeCCCFailLog
DEBUG Dec 14 09:30:49 [listener:1654]: Realising worker 17023
DEBUG Dec 14 09:30:49 [listener:1654]: release_fd_struct: fd '109.TCP.INET.auxilary' is closed
DEBUG Dec 14 09:30:49 [apiInterface:17009]: do_query: Query: 'select servicevalue from tblclientservices where servicekey='CCCEnabled''
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: varname=cccEnable
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: cccEnable.status=0
INFO Dec 14 09:30:49 [apiInterface:17009]: create_act_out_perl_obj: JSON cccEnable.output={ "servicevalue": [ "no" ] }
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Object
DEBUG Dec 14 09:30:49 [apiInterface:17009]: json_to_perl: Array
INFO Dec 14 09:30:49 [apiInterface:17009]: opcode 'apiInterface': time taken: 1.082784915 seconds
DEBUG Dec 14 09:30:49 [worker:17009]: worker_proc: going to release dbhandle for 17009(1,1700901)
DEBUG Dec 14 09:30:49 [worker:17009]: Main TLV:{ 4, data:{ 1, 4, 25F4190} data:{ 2, 4, 714200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:30:49 [worker:17009]: {"response":{"method":"opcode","name":"apiInterface","version":"1.8","type":"text","length":149,"data":{ "Event": "UPDATE", "Entity": "sslvpntunnel", "statusmessage": "Default CA is not configured", "invalidparams": [ "perusercert" ], "status": "501" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:49 [worker:17009]: # OPCODE Exited: 'apiInterface' with Status: '500'
DEBUG Dec 14 09:30:49 [worker:17009]: write_packet: 52+149+2
DEBUG Dec 14 09:30:49 [worker:17009]: write_packet: write 203 bytes to listener
DEBUG Dec 14 09:30:49 [listener:1654]: read_response_from_sockpair: 203 bytes read from sockpair worker 17009
DEBUG Dec 14 09:30:49 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17009
DEBUG Dec 14 09:30:49 [listener:1654]: Received response from worker
DEBUG Dec 14 09:30:49 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 184 bytes to requester
DEBUG Dec 14 09:30:49 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:30:49 [listener:1654]: Worker with pid 17009 got executed, will revive again.
DEBUG Dec 14 09:30:49 [listener:1654]: Worker 17009 is removed from busy list
DEBUG Dec 14 09:30:49 [listener:1654]: csc_waitpid: Process with pid 17009, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:30:49 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 714200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:30:49 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:30:49 [listener:1654]: Realising worker 17024
DEBUG Dec 14 09:30:59 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 59 bytes are read by listener
DEBUG Dec 14 09:30:59 [listener:1654]: register_request_inet: request from port '40888'
INFO Dec 14 09:30:59 [listener:1654]: protocol content type not found
INFO Dec 14 09:30:59 [listener:1654]: Assigning free worker 17024
DEBUG Dec 14 09:30:59 [listener:1654]: assign_to_busy_queue: assigning worker 17024
DEBUG Dec 14 09:30:59 [listener:1654]: send_data_to_sockpair: listener has send 54 bytes to sockpair worker 17024
DEBUG Dec 14 09:30:59 [worker:17024]: read_packet: read() 54 bytes from listener
DEBUG Dec 14 09:30:59 [worker:17024]: # OPCODE Called: 'garnerevent'
MESSAGE Dec 14 09:30:59 [worker:17024]: {"request":{"method":"nopcode","name":"garnerevent","version":"1.8","type":"text","length":2,"data":60}}
DEBUG Dec 14 09:30:59 [worker:17024]: Main TLV:{ 1, data:{ 2, 4, 804200} , 9}
DEBUG Dec 14 09:30:59 [worker:17024]: recv_dbtlv_data: tlv->type(1) : 1702401
DEBUG Dec 14 09:30:59 [worker:17024]: worker_proc: dbhandle init for 17024(1,1702401)
DEBUG Dec 14 09:30:59 [worker:17024]: ### insert_uuid: hdr: len=2 content=1 method=1 name=garnerevent
DEBUG Dec 14 09:30:59 [worker:17024]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:30:59 [worker:17024]: ### insert_uuid: uuid insertion took 0 s 16138 ns
INFO Dec 14 09:31:00 [garnerevent:17024]: creating text object
DEBUG Dec 14 09:31:00 [garnerevent:17024]: ws_do_evlog: FD: 4
DEBUG Dec 14 09:31:00 [garnerevent:17024]: do_evlog_to_file: FD: 4
INFO Dec 14 09:31:00 [garnerevent:17024]: opcode 'garnerevent': time taken: 0.277822035 seconds
DEBUG Dec 14 09:31:00 [worker:17024]: worker_proc: going to release dbhandle for 17024(1,1702401)
DEBUG Dec 14 09:31:00 [worker:17024]: Main TLV:{ 4, data:{ 1, 4, 1FA190} data:{ 2, 4, 804200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:00 [worker:17024]: {"response":{"method":"nopcode","name":"garnerevent","version":"1.8","type":"text","length":0,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:00 [worker:17024]: # OPCODE Exited: 'garnerevent' with Status: '200'
DEBUG Dec 14 09:31:00 [worker:17024]: write_packet: 52+0+2
DEBUG Dec 14 09:31:00 [listener:1654]: read_response_from_sockpair: 54 bytes read from sockpair worker 17024
DEBUG Dec 14 09:31:00 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17024
DEBUG Dec 14 09:31:00 [listener:1654]: Received response from worker
INFO Dec 14 09:31:00 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:31:00 [listener:1654]: Worker with pid 17024 got executed, will revive again.
DEBUG Dec 14 09:31:00 [listener:1654]: Worker 17024 is removed from busy list
DEBUG Dec 14 09:31:00 [listener:1654]: csc_waitpid: Process with pid 17024, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:00 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 804200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:00 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:00 [listener:1654]: Realising worker 17028
DEBUG Dec 14 09:31:02 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 51 bytes are read by listener
DEBUG Dec 14 09:31:02 [listener:1654]: register_request_inet: request from port '57068'
INFO Dec 14 09:31:02 [listener:1654]: protocol content type not found
INFO Dec 14 09:31:02 [listener:1654]: protocol length not found
INFO Dec 14 09:31:02 [listener:1654]: Assigning free worker 17028
DEBUG Dec 14 09:31:02 [listener:1654]: assign_to_busy_queue: assigning worker 17028
DEBUG Dec 14 09:31:02 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 17028
DEBUG Dec 14 09:31:02 [worker:17028]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:31:02 [worker:17028]: # OPCODE Called: 'auth_execute_heartbeat'
MESSAGE Dec 14 09:31:02 [worker:17028]: {"request":{"method":"nopcode","name":"auth_execute_heartbeat","version":"1.8","type":"text","length":0}}
DEBUG Dec 14 09:31:02 [worker:17028]: Main TLV:{ 1, data:{ 2, 4, 844200} , 9}
DEBUG Dec 14 09:31:02 [worker:17028]: recv_dbtlv_data: tlv->type(1) : 1702801
DEBUG Dec 14 09:31:02 [worker:17028]: worker_proc: dbhandle init for 17028(1,1702801)
DEBUG Dec 14 09:31:02 [worker:17028]: ### insert_uuid: hdr: len=0 content=1 method=1 name=auth_execute_heartbeat
DEBUG Dec 14 09:31:02 [worker:17028]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:31:02 [worker:17028]: ### insert_uuid: uuid insertion took 0 s 16576 ns
DEBUG Dec 14 09:31:03 [auth_execute_heartbeat:17028]: do_tlv: tlv listener: authtlv
DEBUG Dec 14 09:31:03 [auth_execute_heartbeat:17028]: TLV SENT 'ASTLV_EXECUTE_HEARTBEAT'
INFO Dec 14 09:31:03 [auth_execute_heartbeat:17028]: opcode 'auth_execute_heartbeat': time taken: 0.276206738 seconds
DEBUG Dec 14 09:31:03 [worker:17028]: worker_proc: going to release dbhandle for 17028(1,1702801)
DEBUG Dec 14 09:31:03 [worker:17028]: Main TLV:{ 4, data:{ 1, 4, 91FB190} data:{ 2, 4, 844200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:03 [worker:17028]: {"response":{"method":"nopcode","name":"auth_execute_heartbeat","version":"1.8","type":"text","length":7,"data":success,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:03 [worker:17028]: # OPCODE Exited: 'auth_execute_heartbeat' with Status: '200'
DEBUG Dec 14 09:31:03 [worker:17028]: write_packet: 52+7+2
DEBUG Dec 14 09:31:03 [listener:1654]: read_response_from_sockpair: 61 bytes read from sockpair worker 17028
DEBUG Dec 14 09:31:03 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17028
DEBUG Dec 14 09:31:03 [listener:1654]: Received response from worker
DEBUG Dec 14 09:31:03 [worker:17028]: write_packet: write 61 bytes to listener
INFO Dec 14 09:31:03 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:31:03 [listener:1654]: Worker with pid 17028 got executed, will revive again.
DEBUG Dec 14 09:31:03 [listener:1654]: Worker 17028 is removed from busy list
DEBUG Dec 14 09:31:03 [listener:1654]: csc_waitpid: Process with pid 17028, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:03 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 844200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:03 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:03 [listener:1654]: Realising worker 17031
DEBUG Dec 14 09:31:03 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 43 bytes are read by listener
DEBUG Dec 14 09:31:03 [listener:1654]: register_request_inet: request from port '44247'
INFO Dec 14 09:31:03 [listener:1654]: protocol content type not found
INFO Dec 14 09:31:03 [listener:1654]: protocol length not found
INFO Dec 14 09:31:03 [listener:1654]: Assigning free worker 17031
DEBUG Dec 14 09:31:03 [listener:1654]: assign_to_busy_queue: assigning worker 17031
DEBUG Dec 14 09:31:03 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 17031
DEBUG Dec 14 09:31:03 [worker:17031]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:31:03 [worker:17031]: # OPCODE Called: 'auth_edir_sync'
MESSAGE Dec 14 09:31:03 [worker:17031]: {"request":{"method":"nopcode","name":"auth_edir_sync","version":"1.8","type":"text","length":0}}
DEBUG Dec 14 09:31:03 [worker:17031]: Main TLV:{ 1, data:{ 2, 4, 874200} , 9}
DEBUG Dec 14 09:31:03 [worker:17031]: recv_dbtlv_data: tlv->type(1) : 1703101
DEBUG Dec 14 09:31:03 [worker:17031]: worker_proc: dbhandle init for 17031(1,1703101)
DEBUG Dec 14 09:31:03 [worker:17031]: ### insert_uuid: hdr: len=0 content=1 method=1 name=auth_edir_sync
DEBUG Dec 14 09:31:03 [worker:17031]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:31:03 [worker:17031]: ### insert_uuid: uuid insertion took 0 s 16391 ns
DEBUG Dec 14 09:31:04 [auth_edir_sync:17031]: do_tlv: tlv listener: authtlv
DEBUG Dec 14 09:31:04 [auth_edir_sync:17031]: TLV SENT 'ASTLV_EDIR_SYNC'
INFO Dec 14 09:31:04 [auth_edir_sync:17031]: opcode 'auth_edir_sync': time taken: 0.275326113 seconds
DEBUG Dec 14 09:31:04 [worker:17031]: worker_proc: going to release dbhandle for 17031(1,1703101)
DEBUG Dec 14 09:31:04 [worker:17031]: Main TLV:{ 4, data:{ 1, 4, BDFC190} data:{ 2, 4, 874200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:04 [worker:17031]: {"response":{"method":"nopcode","name":"auth_edir_sync","version":"1.8","type":"text","length":7,"data":success,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:04 [worker:17031]: # OPCODE Exited: 'auth_edir_sync' with Status: '200'
DEBUG Dec 14 09:31:04 [worker:17031]: write_packet: 52+7+2
DEBUG Dec 14 09:31:04 [worker:17031]: write_packet: write 61 bytes to listener
DEBUG Dec 14 09:31:04 [listener:1654]: read_response_from_sockpair: 61 bytes read from sockpair worker 17031
DEBUG Dec 14 09:31:04 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17031
DEBUG Dec 14 09:31:04 [listener:1654]: Received response from worker
INFO Dec 14 09:31:04 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:31:04 [listener:1654]: Worker with pid 17031 got executed, will revive again.
DEBUG Dec 14 09:31:04 [listener:1654]: Worker 17031 is removed from busy list
DEBUG Dec 14 09:31:04 [listener:1654]: csc_waitpid: Process with pid 17031, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:04 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 874200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:04 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:04 [listener:1654]: Realising worker 17032
DEBUG Dec 14 09:31:07 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 37 bytes are read by listener
DEBUG Dec 14 09:31:07 [listener:1654]: register_request_inet: request from port '46751'
INFO Dec 14 09:31:07 [listener:1654]: protocol content type not found
INFO Dec 14 09:31:07 [listener:1654]: protocol length not found
INFO Dec 14 09:31:07 [listener:1654]: Assigning free worker 17032
DEBUG Dec 14 09:31:07 [listener:1654]: assign_to_busy_queue: assigning worker 17032
DEBUG Dec 14 09:31:07 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 17032
DEBUG Dec 14 09:31:07 [worker:17032]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:31:07 [worker:17032]: # OPCODE Called: 'getappkey'
MESSAGE Dec 14 09:31:07 [worker:17032]: {"request":{"method":"opcode","name":"getappkey","version":"1.10","type":"text","length":0}}
DEBUG Dec 14 09:31:07 [worker:17032]: Main TLV:{ 1, data:{ 2, 4, 884200} , 9}
DEBUG Dec 14 09:31:07 [worker:17032]: recv_dbtlv_data: tlv->type(1) : 1703201
DEBUG Dec 14 09:31:07 [worker:17032]: worker_proc: dbhandle init for 17032(1,1703201)
DEBUG Dec 14 09:31:07 [worker:17032]: ### insert_uuid: hdr: len=0 content=1 method=0 name=getappkey
DEBUG Dec 14 09:31:07 [worker:17032]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:31:07 [worker:17032]: ### insert_uuid: uuid insertion took 0 s 18702 ns
INFO Dec 14 09:31:08 [getappkey:17032]: ACTION: DLOPEN(do_nvram_eget, li.serial)
INFO Dec 14 09:31:08 [getappkey:17032]: do_nvram_eget: li.serial in appkey var
INFO Dec 14 09:31:08 [getappkey:17032]: opcode 'getappkey': time taken: 0.292157652 seconds
DEBUG Dec 14 09:31:08 [worker:17032]: worker_proc: going to release dbhandle for 17032(1,1703201)
DEBUG Dec 14 09:31:08 [worker:17032]: Main TLV:{ 4, data:{ 1, 4, 21FD190} data:{ 2, 4, 884200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:08 [worker:17032]: {"response":{"method":"opcode","name":"getappkey","version":"1.10","type":"text","length":15,"data":C1B103DK2222X35,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:08 [worker:17032]: # OPCODE Exited: 'getappkey' with Status: '200'
DEBUG Dec 14 09:31:08 [worker:17032]: write_packet: 52+15+2
DEBUG Dec 14 09:31:08 [listener:1654]: read_response_from_sockpair: 69 bytes read from sockpair worker 17032
DEBUG Dec 14 09:31:08 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17032
DEBUG Dec 14 09:31:08 [listener:1654]: Received response from worker
DEBUG Dec 14 09:31:08 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 50 bytes to requester
DEBUG Dec 14 09:31:08 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:31:08 [listener:1654]: Worker with pid 17032 got executed, will revive again.
DEBUG Dec 14 09:31:08 [listener:1654]: Worker 17032 is removed from busy list
DEBUG Dec 14 09:31:08 [listener:1654]: csc_waitpid: Process with pid 17032, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:08 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 884200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:08 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:08 [listener:1654]: Realising worker 17040
DEBUG Dec 14 09:31:08 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 40 bytes are read by listener
DEBUG Dec 14 09:31:08 [listener:1654]: register_request_inet: request from port '38736'
INFO Dec 14 09:31:08 [listener:1654]: protocol content type not found
INFO Dec 14 09:31:08 [listener:1654]: protocol length not found
INFO Dec 14 09:31:08 [listener:1654]: Assigning free worker 17040
DEBUG Dec 14 09:31:08 [listener:1654]: assign_to_busy_queue: assigning worker 17040
DEBUG Dec 14 09:31:08 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to sockpair worker 17040
DEBUG Dec 14 09:31:08 [worker:17040]: read_packet: read() 52 bytes from listener
DEBUG Dec 14 09:31:08 [worker:17040]: # OPCODE Called: 'getpublickey'
MESSAGE Dec 14 09:31:08 [worker:17040]: {"request":{"method":"opcode","name":"getpublickey","version":"1.10","type":"text","length":0}}
DEBUG Dec 14 09:31:08 [worker:17040]: Main TLV:{ 1, data:{ 2, 4, 904200} , 9}
DEBUG Dec 14 09:31:08 [worker:17040]: recv_dbtlv_data: tlv->type(1) : 1704001
DEBUG Dec 14 09:31:08 [worker:17040]: worker_proc: dbhandle init for 17040(1,1704001)
DEBUG Dec 14 09:31:08 [worker:17040]: ### insert_uuid: hdr: len=0 content=1 method=0 name=getpublickey
DEBUG Dec 14 09:31:08 [worker:17040]: ### insert_uuid: skipping uuid insertion
DEBUG Dec 14 09:31:08 [worker:17040]: ### insert_uuid: uuid insertion took 0 s 23400 ns
INFO Dec 14 09:31:08 [getpublickey:17040]: ACTION: CALL init_interface_array
INFO Dec 14 09:31:08 [getpublickey:17040]: ACTION: DLOPEN(do_getenv, APPLIANCE)
INFO Dec 14 09:31:08 [getpublickey:17040]: ACTION: DLOPEN(getkey, cports)
INFO Dec 14 09:31:08 [getpublickey:17040]: do_nvram_get: newkey var
MESSAGE Dec 14 09:31:08 [getpublickey:17040]: nvram_get(newkey:1) succeed
DEBUG Dec 14 09:31:08 [getpublickey:17040]: get_mac_add: mac used for port(Port1) '1249028126230211'
DEBUG Dec 14 09:31:08 [getpublickey:17040]: get_mac_add: mac used for port(Port2) '1249028126230212'
DEBUG Dec 14 09:31:08 [getpublickey:17040]: generate_new_key: final string '12490281262302111249028126230212C1B103DK2222X35'
DEBUG Dec 14 09:31:08 [getpublickey:17040]: sha_key: 'dfd16b36b24f4de3eb6efc5437590022e82e'
DEBUG Dec 14 09:31:08 [getpublickey:17040]: logger: applog
DEBUG Dec 14 09:31:08 [getpublickey:17040]: do_log_to_file: length=64
IFNAME_PREFIX: Port
IFNAME_SUFFIX: NUM
IFLIST: PORT_1-9
INFO Dec 14 09:31:08 [getpublickey:17040]: opcode 'getpublickey': time taken: 0.291633686 seconds
DEBUG Dec 14 09:31:08 [worker:17040]: worker_proc: going to release dbhandle for 17040(1,1704001)
DEBUG Dec 14 09:31:08 [worker:17040]: Main TLV:{ 4, data:{ 1, 4, 4101A0} data:{ 2, 4, 904200} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:08 [worker:17040]: {"response":{"method":"opcode","name":"getpublickey","version":"1.10","type":"text","length":36,"data":dfd16b36b24f4de3eb6efc5437590022e82e,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:08 [worker:17040]: # OPCODE Exited: 'getpublickey' with Status: '200'
DEBUG Dec 14 09:31:08 [worker:17040]: write_packet: 52+36+2
DEBUG Dec 14 09:31:08 [worker:17040]: write_packet: write 90 bytes to listener
DEBUG Dec 14 09:31:08 [listener:1654]: read_response_from_sockpair: 90 bytes read from sockpair worker 17040
DEBUG Dec 14 09:31:08 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 17040
DEBUG Dec 14 09:31:08 [listener:1654]: Received response from worker
DEBUG Dec 14 09:31:08 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 71 bytes to requester
DEBUG Dec 14 09:31:08 [listener:1654]: Listener has sent data to requester
DEBUG Dec 14 09:31:08 [listener:1654]: Worker with pid 17040 got executed, will revive again.
DEBUG Dec 14 09:31:08 [listener:1654]: Worker 17040 is removed from busy list
DEBUG Dec 14 09:31:08 [listener:1654]: csc_waitpid: Process with pid 17040, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:08 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 904200} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:08 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:08 [listener:1654]: Realising worker 17046
DEBUG Dec 14 09:31:09 [listener:1654]: ln_recvfrom: fd '5.UDP.INET.server': 42 bytes are read by listener
DEBUG Dec 14 09:31:09 [listener:1654]: register_request_inet: request from port '46252'
INFO Dec 14 09:31:09 [listener:1654]: protocol content type not found
INFO Dec 14 09:31:09 [listener:1654]: protocol length not found
DEBUG Dec 14 09:31:09 [listener:1654]: send_data_to_sockpair: listener has send 52 bytes to
DEBUG Dec 14 09:31:09 [listener:1654]: read_response_from_sockpair: 217 bytes read from
DEBUG Dec 14 09:31:09 [listener:1654]: is_response_complete: Complete response is received from
DEBUG Dec 14 09:31:09 [listener:1654]: Received response from worker
DEBUG Dec 14 09:31:09 [listener:1654]: ln_sendto: fd '5.UDP.INET.server' has sent 217 bytes to requester
DEBUG Dec 14 09:31:09 [listener:1654]: Listener has sent data to requester
INFO Dec 14 09:31:09 [restart_tomcat:16736]: csc_execve: Child exited with status 0
DEBUG Dec 14 09:31:09 [restart_tomcat:16736]: log_exec: Command: /scripts/system/restart_tomcat.sh
INFO Dec 14 09:31:09 [restart_tomcat:16736]: opcode 'restart_tomcat': time taken: 70.043870769 seconds
DEBUG Dec 14 09:31:09 [worker:16736]: worker_proc: going to release dbhandle for 16736(1,1673602)
DEBUG Dec 14 09:31:09 [worker:16736]: Main TLV:{ 4, data:{ 1, 4, 8289190} data:{ 2, 4, 604100} data:{ 5, 4, 0000} , 27}
DEBUG Dec 14 09:31:09 [worker:16736]: {"response":{"method":"nopcode","name":"restart_tomcat","version":"1.8","type":"text","length":0,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:31:09 [worker:16736]: # OPCODE Exited: 'restart_tomcat' with Status: '200'
DEBUG Dec 14 09:31:09 [worker:16736]: write_packet: 52+0+2
DEBUG Dec 14 09:31:09 [worker:16736]: write_packet: write 54 bytes to listener
DEBUG Dec 14 09:31:09 [listener:1654]: read_response_from_sockpair: 54 bytes read from sockpair worker 16736
DEBUG Dec 14 09:31:09 [listener:1654]: is_response_complete: Complete response is received from sockpair worker 16736
DEBUG Dec 14 09:31:09 [listener:1654]: Received response from worker
INFO Dec 14 09:31:09 [listener:1654]: send_buffer_to_requester: Not sending response to requester
DEBUG Dec 14 09:31:09 [listener:1654]: Worker with pid 16736 got executed, will revive again.
DEBUG Dec 14 09:31:09 [listener:1654]: Worker 16736 is removed from busy list
DEBUG Dec 14 09:31:09 [listener:1654]: csc_waitpid: Process with pid 16736, wrapped-up successfully using signal 9.
DEBUG Dec 14 09:31:09 [listener:1654]: Main TLV:{ 4, data:{ 1, 4, 0000} data:{ 2, 4, 604100} data:{ 5, 4, 1000} , 27}
DEBUG Dec 14 09:31:09 [listener:1654]: csc_socketpair called: biggest fd is 109
DEBUG Dec 14 09:31:09 [listener:1654]: Realising worker 17075
^C
XG135_XN03_SFOS 18.0.3 MR-3# csc custom debug
XG135_XN03_SFOS 18.0.3 MR-3#
Hi Kay Werrmann,
Thank you for providing debug logs.
As per the following log entries, the issue is that the firewall's default certificate is not configured, or the name of the certificate has some special characters or space in it.
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: opcode 'sslvpn_global_settings': time taken: 0.283496160 seconds
DEBUG Dec 14 09:30:34 [worker:16934]: {"response":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"text","length":104,"data":{ "statusmessage": "Default CA is not configured", "invalidparams": [ "perusercert" ], "status": "501" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:34 [worker:16934]: # OPCODE Exited: 'sslvpn_global_settings' with Status: '500'
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: 52+104+2
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: write 158 bytes to listener
Could you please ensure default CA details are properly configured on your firewall? Let us know if that resolves your issue.
Thanks,
Hi Kay Werrmann,
Thank you for providing debug logs.
As per the following log entries, the issue is that the firewall's default certificate is not configured, or the name of the certificate has some special characters or space in it.
INFO Dec 14 09:30:34 [sslvpn_global_settings:16934]: opcode 'sslvpn_global_settings': time taken: 0.283496160 seconds
DEBUG Dec 14 09:30:34 [worker:16934]: {"response":{"method":"opcode","name":"sslvpn_global_settings","version":"1.14","type":"text","length":104,"data":{ "statusmessage": "Default CA is not configured", "invalidparams": [ "perusercert" ], "status": "501" },"statusCode":500,"statusStrlen":2,"statusString":"OK"}}
DEBUG Dec 14 09:30:34 [worker:16934]: # OPCODE Exited: 'sslvpn_global_settings' with Status: '500'
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: 52+104+2
DEBUG Dec 14 09:30:34 [worker:16934]: write_packet: write 158 bytes to listener
Could you please ensure default CA details are properly configured on your firewall? Let us know if that resolves your issue.
Thanks,
Hello Harsh Patel,
The customer has registered the firewall in the My Sophos portal to a company name with a special character. So the default certificate was also with a special character.
After changing the default certificate, the setting in the "Show VPN settings" dialogue is now also possible.
Thank you very much for your support and best regards,
Kay Werrmann
