Guest User!

You are not Sophos Staff.

Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 2 replies
  • Subscribers 26 subscribers
  • Views 1088 views
  • Users 0 members are here
Options
Suggested
This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Remove authentication server from XG

RalphScharping

Hi,

I am new to XG and playing in a test environment.  So far I have been successful in getting everything I have tried up and running.

Through some hiccups I have caused by messing with stuff, I have eliminated the domain controller that I had added my XG to, earlier.  Even though I set up a new domain controller using the same IP address the connection to XG is no longer operational.

When I try to remove the linked DC, I get this message:

I have been stuck on this for about a week now, rebooted the firewall multiple times and also waited much longer than I should have.  There is nothing in the logs that gives me any clues. 

Does anyone have an Idea?



This thread was automatically locked due to age.
Parents
  • FormerMember
    0 FormerMember

    Hi ,

    Thank you for reaching out to the Community!

    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

    • To connect using SSH, you may use any SSH client to connect to port 22 of the SFOS device.
    • Select option 5 Device Management.
    • Select option 3 Advanced Shell.

    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,

  • 0 in reply to FormerMember

    Hi H_Patel,

    thank you for your answer and your instructions.  I was away from the office yesterday, excuse the delay.  Please find enclosed the requested logs:

    Applog:

    SFVH_VM01_SFOS 18.0.4 MR-4# tail -f /log/applog.log
    Feb 09 10:36:16 apiInterface:Current ver :::'1800.2'
    Feb 09 10:36:16 apiInterface:entityjson::::::::HASH(0xaf43390)
    Feb 09 10:36:16 Info:: Transaction will not be rolled back for opcode lic_subinfo. If any operation fails, request is part of multiple request :
    Feb 09 10:36:17 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:36:17 Request type = 1
    Feb 09 10:36:17 apiInterface:versionsupported: true.
    Feb 09 10:36:17 apiInterface:request mode -> 2505.
    Feb 09 10:36:17 apiInterface:Current ver :::'1800.2'
    Feb 09 10:36:17 apiInterface:entityjson::::::::HASH(0xaf43390)
    Feb 09 10:36:17 Info:: Transaction will not be rolled back for opcode check_rdm. If any operation fails, request is part of multiple request :
    Feb 09 10:38:21 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:38:21 Request type = 1
    Feb 09 10:38:21 apiInterface:versionsupported: true.
    Feb 09 10:38:21 apiInterface:request mode -> 473.
    Feb 09 10:38:21 apiInterface:Current ver :::'1800.2'
    Feb 09 10:38:21 apiInterface:entityjson::::::::
    Feb 09 10:38:21 Info:: Transaction will not be rolled back for opcode delete_AUTH_server. If any operation fails, request is part of multiple request :
    Feb 09 10:38:22 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:38:22 Request type = 1
    Feb 09 10:38:22 apiInterface:versionsupported: true.
    Feb 09 10:38:22 apiInterface:request mode -> 19.
    Feb 09 10:38:22 apiInterface:Current ver :::'1500.1'
    Feb 09 10:38:22 apiInterface:entityjson::::::::
    Feb 09 10:38:22 Info:: Transaction will not be rolled back for opcode delete_ADS_server. If any operation fails, request is part of multiple request :
    Feb 09 10:38:22 Inside Funtion
    Feb 09 10:38:22 call for ADS------------------------------> 1
    Feb 09 10:38:22 Inside
    Feb 09 10:38:22 Opcode Fail
    Feb 09 10:38:22 Fail Opcode
    Feb 09 10:38:28  l2dhcp_commit : 10.222.222.63 , 9e:14:96:16:dc:9e , 0 , PortB

    csc:

    DEBUG     Feb 09 10:40:28  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6126
    DEBUG     Feb 09 10:40:28  [listener:1015]: Received response from worker
    INFO      Feb 09 10:40:28  [listener:1015]: send_buffer_to_requester: Not sending response to requester
    DEBUG     Feb 09 10:40:28  [listener:1015]: Worker with pid 6126 got executed, will revive again.
    INFO      Feb 09 10:40:28  [worker:6126]: Closing worker
    DEBUG     Feb 09 10:40:28  [listener:1015]: Worker 6126 is removed from busy list
    DEBUG     Feb 09 10:40:28  [listener:1015]: csc_waitpid: Process with pid 6126, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:28  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  EE1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:28  [listener:1015]: csc_socketpair called: biggest fd is 111
    DEBUG     Feb 09 10:40:28  [listener:1015]: Realising worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: ln_recvfrom: fd '5.UDP.INET.server': 390 bytes are read by listener
    DEBUG     Feb 09 10:40:44  [listener:1015]: register_request_inet: request from port '44272'
    INFO      Feb 09 10:40:44  [listener:1015]: protocol dbhandle not found
    INFO      Feb 09 10:40:44  [listener:1015]: Assigning free worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: assign_to_busy_queue: assigning worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: send_data_to_sockpair: listener has send 376 bytes to sockpair worker 6135
    DEBUG     Feb 09 10:40:44  [worker:6135]: read_packet: read() 376 bytes from listener
    DEBUG     Feb 09 10:40:44  [worker:6135]: # OPCODE Called: 'apiInterface'
    MESSAGE   Feb 09 10:40:44  [worker:6135]: {"request":{"method":"opcode","name":"apiInterface","version":"1.8","type":"json","length":324,"data":{"___serverport":4444,"select":["DNS-SRV"],"___component":"GUI","transactionid":"412","mode":473,"currentlyloggedinuserid":3,"APIVersion":"1800.2","___serverprotocol":"HTTP","adsserverids":"DNS-SRV","___username":"admin","___meta":{"sessionType":1},"___serverip":"192.168.222.253","currentlyloggedinuserip":"192.168.222.36"}}}
    DEBUG     Feb 09 10:40:44  [worker:6135]: Main TLV:{ 1, data:{ 2, 4,  F71700} , 9}
    DEBUG     Feb 09 10:40:44  [worker:6135]: recv_dbtlv_data: tlv->type(1) : 613501
    DEBUG     Feb 09 10:40:44  [worker:6135]: worker_proc: dbhandle init for 6135(1,613501)
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: hdr: len=324 content=0 method=0 name=apiInterface
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: uuid insertion took 0 s 34367 ns
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [apiInterface:6135]: creating json object
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL sanitizeRequest
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: Initializing database handle
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select case when usertype in (1,7) then 'adminuser' else 'normaluser' end as usertype from tbluser where userid=3'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=curLoggedIn
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: curLoggedIn.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON curLoggedIn.output={ "usertype": [ "adminuser" ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=72
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL variableInitialization
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: Txid:468028
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'start transaction'
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=17
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL isAPIVersionSupported
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=37
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL opcodePreProcess
    INFO      Feb 09 10:40:45  [apiInterface:6135]: executing FORLOOP
    INFO      Feb 09 10:40:45  [apiInterface:6135]: FORLOOP condition true
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL checkUserPermission
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select entityid from tblcrevent where mode  = 473'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "entityid": [ 42 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select cmstatus from tblcentralmgmt'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=CMResult
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: CMResult.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON CMResult.output={ "cmstatus": [ 0 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select roleid from tbluserrolerelation where userid = 3'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "roleid": [ 1 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select operationallowed from tblacldefinition where roleid = 1 and entityid = 42'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "operationallowed": [ 15 ] }
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL preMigration
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL createModeJSON
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=34
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL migrateToCurrVersion
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=38
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL createJson
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL validateJson
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=32
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL handleDeleteRequest
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL replyIfErrorAtValidation
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL getOldObject
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=473'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=opout
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: opout.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON opout.output={ "opcode": [ "delete_AUTH_server" ], "opcodetype": [ "2" ], "perlpackagename": [ "" ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=137
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: execute_action: DYNACODE variable:opcodename
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: execute_action: DYNACODE opcode:delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_ao: OPCODE delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_ao: OPCODE delete_AUTH_server CONTENT-TYPE:json, BODY_LEN:398
    DEBUG     Feb 09 10:40:45  [listener:1015]: ln_recvfrom: fd '111.TCP.INET.auxilary': 486 bytes are read by listener
    DEBUG     Feb 09 10:40:45  [listener:1015]: register_request_inet: request from port '0'
    INFO      Feb 09 10:40:45  [listener:1015]: Assigning free worker 6079
    DEBUG     Feb 09 10:40:45  [listener:1015]: assign_to_busy_queue: assigning worker 6079
    DEBUG     Feb 09 10:40:45  [listener:1015]: send_data_to_sockpair: listener has send 450 bytes to sockpair worker 6079
    DEBUG     Feb 09 10:40:45  [worker:6079]: read_packet: read() 450 bytes from listener
    DEBUG     Feb 09 10:40:45  [worker:6079]: # OPCODE Called: 'delete_AUTH_server'
    MESSAGE   Feb 09 10:40:45  [worker:6079]: {"request":{"method":"opcode","name":"delete_AUTH_server","version":"1.14","type":"json","length":398,"data":{ "Event": "DELETE", "select": [ "DNS-SRV" ], "adsserverids": "DNS-SRV", "___serverprotocol": "HTTP", "___component": "GUI", "Entity": "adsserver", "___username": "admin", "mode": 473, "___meta": { "sessionType": 1 }, "___serverport": 4444, "currentlyloggedinuserip": "192.168.222.36", "___serverip": "192.168.222.253", "APIVersion": "1800.2", "transactionid": "412", "currentlyloggedinuserid": 3 }}}
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: hdr: len=398 content=0 method=0 name=delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: skipping uuid insertion
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: uuid insertion took 0 s 24665 ns
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: creating json object
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: Initializing database handle
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(serverid || ','),0,length(mergetext(serverid || ','))) as serverid from tblradiusauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.id || ','),0,length(mergetext(a.id || ','))) as serverid from tbltacacsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.serverid || ','),0,length(mergetext(a.serverid || ','))) as serverid from tbladsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid and a.servertype=1'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "1" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.serverid || ','),0,length(mergetext(a.serverid || ','))) as serverid from tbladsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid and a.servertype=2'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: ACTION: CALL add_extra_pera
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_ao: OPCODE apiInterface
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_ao: OPCODE apiInterface CONTENT-TYPE:json, BODY_LEN:176
    DEBUG     Feb 09 10:40:45  [listener:1015]: ln_recvfrom: fd '5.UDP.INET.server': 258 bytes are read by listener
    DEBUG     Feb 09 10:40:45  [listener:1015]: register_request_inet: request from port '56305'
    INFO      Feb 09 10:40:45  [listener:1015]: Assigning free worker 6078
    DEBUG     Feb 09 10:40:45  [listener:1015]: assign_to_busy_queue: assigning worker 6078
    DEBUG     Feb 09 10:40:45  [listener:1015]: send_data_to_sockpair: listener has send 228 bytes to sockpair worker 6078
    DEBUG     Feb 09 10:40:45  [worker:6078]: read_packet: read() 228 bytes from listener
    DEBUG     Feb 09 10:40:45  [worker:6078]: # OPCODE Called: 'apiInterface'
    MESSAGE   Feb 09 10:40:45  [worker:6078]: {"request":{"method":"opcode","name":"apiInterface","version":"1.14","type":"json","length":176,"data":{ "___caller": "system", "___username": "admin", "serverid": [ "1" ], "currentlyloggedinuserip": "192.168.222.36", "mode": "19", "APIVersion": "1500.1", "___component": "GUI" }}}
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: hdr: len=176 content=0 method=0 name=apiInterface
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: uuid insertion took 0 s 29490 ns
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [apiInterface:6078]: creating json object
    INFO      Feb 09 10:40:45  [apiInterface:6078]: ACTION: CALL sanitizeRequest
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: do_log_to_file: length=72
    INFO      Feb 09 10:40:45  [apiInterface:6078]: ACTION: CALL variableInitialization
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: Initializing database handle
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: Txid:468033
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'start transaction'
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=17
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL isAPIVersionSupported
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=37
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL opcodePreProcess
    INFO      Feb 09 10:40:46  [apiInterface:6078]: executing FORLOOP
    INFO      Feb 09 10:40:46  [apiInterface:6078]: FORLOOP condition true
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL checkUserPermission
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select userid from tbluser where username= '$currentUser''
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=curLogOut
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: curLogOut.status=0
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select entityid from tblcrevent where mode  = $request->{mode}'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL preMigration
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL createModeJSON
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=33
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL migrateToCurrVersion
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=38
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL createJson
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL validateJson
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=32
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL handleDeleteRequest
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL replyIfErrorAtValidation
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL getOldObject
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=$request->{mode}'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=opout
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: opout.status=0
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=136
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: execute_action: DYNACODE variable:opcodename
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: execute_action: DYNACODE opcode:delete_ADS_server
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_ao: OPCODE delete_ADS_server
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_ao: OPCODE delete_ADS_server CONTENT-TYPE:json, BODY_LEN:206
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_recvfrom: fd '112.TCP.INET.auxilary': 293 bytes are read by listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: register_request_inet: request from port '0'
    INFO      Feb 09 10:40:46  [listener:1015]: Assigning free worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: assign_to_busy_queue: assigning worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: send_data_to_sockpair: listener has send 258 bytes to sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [worker:6077]: read_packet: read() 258 bytes from listener
    DEBUG     Feb 09 10:40:46  [worker:6077]: # OPCODE Called: 'delete_ADS_server'
    MESSAGE   Feb 09 10:40:46  [worker:6077]: {"request":{"method":"opcode","name":"delete_ADS_server","version":"1.14","type":"json","length":206,"data":{ "___component": "GUI", "mode": "19", "currentlyloggedinuserip": "192.168.222.36", "serverid": [ "1" ], "currentlyloggedinuserid": 3, "___caller": "system", "___username": "admin", "APIVersion": "1500.1" }}}
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: hdr: len=206 content=0 method=0 name=delete_ADS_server
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: skipping uuid insertion
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: uuid insertion took 0 s 24835 ns
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: creating json object
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: Initializing database handle
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: Txid:468034
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'start transaction'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: ACTION: CALL delete_LDAP_and_ADS_server
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=16
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: traversing scalar 'serverid' over 'serverids'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select count(*) as count from tblauthsettings where authserverid = (select authserverid from tbladsauthserver where serverid=$serverid)'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=resultq
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: resultq.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=46
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=8
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select servertype,authserverid from tbladsauthserver where serverid =$serverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: result.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select name from tblauthserverconfig where id=$authserverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=authServerName
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: authServerName.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select serverdomainrelid from tbladsserverdomainrel where serverid = $serverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: traversing scalar 'domainid' over 'domainids'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsdomainsearchqueryrel where serverdomainrelid=$domainid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsserverdomainrel where serverid = $serverid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsauthserver where serverid = $serverid'
    ERROR     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Failed Query: 'delete from tblauthserverconfig where id=$authserverid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'rollback'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: opcode 'delete_ADS_server': time taken: 0.274450545 seconds
    DEBUG     Feb 09 10:40:46  [worker:6077]: # OPCODE Exited: 'delete_ADS_server' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6077]: write_packet: 52+6+2
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 60 bytes read from sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '112.TCP.INET.auxilary' has sent 40 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6077 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6077 is removed from busy list
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: out.status=500
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: out.error=OK
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'rollback'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL replyFailureMessage
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [apiInterface:6078]: json_tokener_parse: invalid json string: 'failed'

     PAckage ::::cscvalidation/identity/AuthenticationServer.plDEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6077, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BD1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 113
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6165
    DEBUG     Feb 09 10:40:46  [listener:1015]: release_fd_struct: fd '112.TCP.INET.auxilary' is closed
    INFO      Feb 09 10:40:46  [apiInterface:6078]: opcode 'apiInterface': time taken: 0.673379274 seconds
    DEBUG     Feb 09 10:40:46  [worker:6078]: # OPCODE Exited: 'apiInterface' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6078]: write_packet: 52+0+13
    DEBUG     Feb 09 10:40:46  [worker:6078]: write_packet: write 65 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 65 bytes read from sockpair worker 6078
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6078
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '5.UDP.INET.server' has sent 28 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6078 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6078 is removed from busy list
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=adsserverout
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: adsserverout.status=500
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: adsserverout.error=Opcode Failed
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_log_to_file: length=13
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [delete_AUTH_server:6079]: get_string_from_var : 'response' is not a string
    ERROR     Feb 09 10:40:46  [delete_AUTH_server:6079]: json_tokener_parse: invalid json string: 'response'
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_log_to_file: length=13
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: CALL LOG_MESSAGE
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: DLOPEN(get_time, (null))
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: ws_do_evlog: FD: 4
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_evlog_to_file: FD: 4
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6078, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BE1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 112
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6170
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: opcode 'delete_AUTH_server': time taken: 0.950426280 seconds
    DEBUG     Feb 09 10:40:46  [worker:6079]: {"response":{"method":"opcode","name":"delete_AUTH_server","version":"1.14","type":"text","length":0,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
    DEBUG     Feb 09 10:40:46  [worker:6079]: # OPCODE Exited: 'delete_AUTH_server' with Status: '200'
    DEBUG     Feb 09 10:40:46  [worker:6079]: write_packet: 52+0+2
    DEBUG     Feb 09 10:40:46  [worker:6079]: write_packet: write 54 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 54 bytes read from sockpair worker 6079
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6079
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '111.TCP.INET.auxilary' has sent 17 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6079 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6079 is removed from busy list
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: out.status=200
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: out.error=OK
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition false
    DEBUG     Feb 09 10:40:46  [apiInterface:6135]: do_query: Query: 'commit'
    INFO      Feb 09 10:40:46  [apiInterface:6135]: executing FORLOOP
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition true
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition false
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: CALL generateAuditLog
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: CALL replySuccessMessage
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6079, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BF1700} data:{ 5, 4,  1000} , 27}
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [apiInterface:6135]: get_string_from_var : 'response' is not a string
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 112
    ERROR     Feb 09 10:40:46  [apiInterface:6135]: json_tokener_parse: invalid json string: 'response'

     PAckage ::::cscvalidation/identity/AuthenticationServer.plDEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6171
    DEBUG     Feb 09 10:40:46  [listener:1015]: release_fd_struct: fd '111.TCP.INET.auxilary' is closed
    INFO      Feb 09 10:40:46  [apiInterface:6135]: opcode 'apiInterface': time taken: 1.417621691 seconds
    DEBUG     Feb 09 10:40:46  [worker:6135]: worker_proc: going to release dbhandle for 6135(1,613501)
    DEBUG     Feb 09 10:40:46  [worker:6135]: Main TLV:{ 4, data:{ 1, 4,  7D5C90} data:{ 2, 4,  F71700} data:{ 5, 4,  0000} , 27}
    DEBUG     Feb 09 10:40:46  [worker:6135]: {"response":{"method":"opcode","name":"apiInterface","version":"1.8","type":"text","length":0,"statusCode":500,"statusStrlen":13,"statusString":"Opcode Failed"}}
    DEBUG     Feb 09 10:40:46  [worker:6135]: # OPCODE Exited: 'apiInterface' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6135]: write_packet: 52+0+13
    DEBUG     Feb 09 10:40:46  [worker:6135]: write_packet: write 65 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 65 bytes read from sockpair worker 6135
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6135
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '5.UDP.INET.server' has sent 27 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6135 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6135 is removed from busy list
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6135, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  F71700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 111
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6172

Reply
  • 0 in reply to FormerMember

    Hi H_Patel,

    thank you for your answer and your instructions.  I was away from the office yesterday, excuse the delay.  Please find enclosed the requested logs:

    Applog:

    SFVH_VM01_SFOS 18.0.4 MR-4# tail -f /log/applog.log
    Feb 09 10:36:16 apiInterface:Current ver :::'1800.2'
    Feb 09 10:36:16 apiInterface:entityjson::::::::HASH(0xaf43390)
    Feb 09 10:36:16 Info:: Transaction will not be rolled back for opcode lic_subinfo. If any operation fails, request is part of multiple request :
    Feb 09 10:36:17 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:36:17 Request type = 1
    Feb 09 10:36:17 apiInterface:versionsupported: true.
    Feb 09 10:36:17 apiInterface:request mode -> 2505.
    Feb 09 10:36:17 apiInterface:Current ver :::'1800.2'
    Feb 09 10:36:17 apiInterface:entityjson::::::::HASH(0xaf43390)
    Feb 09 10:36:17 Info:: Transaction will not be rolled back for opcode check_rdm. If any operation fails, request is part of multiple request :
    Feb 09 10:38:21 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:38:21 Request type = 1
    Feb 09 10:38:21 apiInterface:versionsupported: true.
    Feb 09 10:38:21 apiInterface:request mode -> 473.
    Feb 09 10:38:21 apiInterface:Current ver :::'1800.2'
    Feb 09 10:38:21 apiInterface:entityjson::::::::
    Feb 09 10:38:21 Info:: Transaction will not be rolled back for opcode delete_AUTH_server. If any operation fails, request is part of multiple request :
    Feb 09 10:38:22 apiInterface:: Deleting Entity and Event for legacy mode base operation
    Feb 09 10:38:22 Request type = 1
    Feb 09 10:38:22 apiInterface:versionsupported: true.
    Feb 09 10:38:22 apiInterface:request mode -> 19.
    Feb 09 10:38:22 apiInterface:Current ver :::'1500.1'
    Feb 09 10:38:22 apiInterface:entityjson::::::::
    Feb 09 10:38:22 Info:: Transaction will not be rolled back for opcode delete_ADS_server. If any operation fails, request is part of multiple request :
    Feb 09 10:38:22 Inside Funtion
    Feb 09 10:38:22 call for ADS------------------------------> 1
    Feb 09 10:38:22 Inside
    Feb 09 10:38:22 Opcode Fail
    Feb 09 10:38:22 Fail Opcode
    Feb 09 10:38:28  l2dhcp_commit : 10.222.222.63 , 9e:14:96:16:dc:9e , 0 , PortB

    csc:

    DEBUG     Feb 09 10:40:28  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6126
    DEBUG     Feb 09 10:40:28  [listener:1015]: Received response from worker
    INFO      Feb 09 10:40:28  [listener:1015]: send_buffer_to_requester: Not sending response to requester
    DEBUG     Feb 09 10:40:28  [listener:1015]: Worker with pid 6126 got executed, will revive again.
    INFO      Feb 09 10:40:28  [worker:6126]: Closing worker
    DEBUG     Feb 09 10:40:28  [listener:1015]: Worker 6126 is removed from busy list
    DEBUG     Feb 09 10:40:28  [listener:1015]: csc_waitpid: Process with pid 6126, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:28  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  EE1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:28  [listener:1015]: csc_socketpair called: biggest fd is 111
    DEBUG     Feb 09 10:40:28  [listener:1015]: Realising worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: ln_recvfrom: fd '5.UDP.INET.server': 390 bytes are read by listener
    DEBUG     Feb 09 10:40:44  [listener:1015]: register_request_inet: request from port '44272'
    INFO      Feb 09 10:40:44  [listener:1015]: protocol dbhandle not found
    INFO      Feb 09 10:40:44  [listener:1015]: Assigning free worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: assign_to_busy_queue: assigning worker 6135
    DEBUG     Feb 09 10:40:44  [listener:1015]: send_data_to_sockpair: listener has send 376 bytes to sockpair worker 6135
    DEBUG     Feb 09 10:40:44  [worker:6135]: read_packet: read() 376 bytes from listener
    DEBUG     Feb 09 10:40:44  [worker:6135]: # OPCODE Called: 'apiInterface'
    MESSAGE   Feb 09 10:40:44  [worker:6135]: {"request":{"method":"opcode","name":"apiInterface","version":"1.8","type":"json","length":324,"data":{"___serverport":4444,"select":["DNS-SRV"],"___component":"GUI","transactionid":"412","mode":473,"currentlyloggedinuserid":3,"APIVersion":"1800.2","___serverprotocol":"HTTP","adsserverids":"DNS-SRV","___username":"admin","___meta":{"sessionType":1},"___serverip":"192.168.222.253","currentlyloggedinuserip":"192.168.222.36"}}}
    DEBUG     Feb 09 10:40:44  [worker:6135]: Main TLV:{ 1, data:{ 2, 4,  F71700} , 9}
    DEBUG     Feb 09 10:40:44  [worker:6135]: recv_dbtlv_data: tlv->type(1) : 613501
    DEBUG     Feb 09 10:40:44  [worker:6135]: worker_proc: dbhandle init for 6135(1,613501)
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: hdr: len=324 content=0 method=0 name=apiInterface
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
    DEBUG     Feb 09 10:40:44  [worker:6135]: ### insert_uuid: uuid insertion took 0 s 34367 ns
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [apiInterface:6135]: creating json object
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL sanitizeRequest
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: Initializing database handle
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select case when usertype in (1,7) then 'adminuser' else 'normaluser' end as usertype from tbluser where userid=3'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=curLoggedIn
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: curLoggedIn.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON curLoggedIn.output={ "usertype": [ "adminuser" ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=72
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL variableInitialization
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: Txid:468028
    INFO      Feb 09 10:40:45  [apiInterface:6135]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'start transaction'
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=17
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL isAPIVersionSupported
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=37
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL opcodePreProcess
    INFO      Feb 09 10:40:45  [apiInterface:6135]: executing FORLOOP
    INFO      Feb 09 10:40:45  [apiInterface:6135]: FORLOOP condition true
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL checkUserPermission
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select entityid from tblcrevent where mode  = 473'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "entityid": [ 42 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select cmstatus from tblcentralmgmt'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=CMResult
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: CMResult.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON CMResult.output={ "cmstatus": [ 0 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select roleid from tbluserrolerelation where userid = 3'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "roleid": [ 1 ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select operationallowed from tblacldefinition where roleid = 1 and entityid = 42'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON result.output={ "operationallowed": [ 15 ] }
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL preMigration
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL createModeJSON
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=34
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL migrateToCurrVersion
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=38
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL createJson
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL validateJson
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=32
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL handleDeleteRequest
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL replyIfErrorAtValidation
    INFO      Feb 09 10:40:45  [apiInterface:6135]: ACTION: CALL getOldObject
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=473'
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: varname=opout
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: opout.status=0
    INFO      Feb 09 10:40:45  [apiInterface:6135]: create_act_out_perl_obj: JSON opout.output={ "opcode": [ "delete_AUTH_server" ], "opcodetype": [ "2" ], "perlpackagename": [ "" ] }
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_log_to_file: length=137
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: execute_action: DYNACODE variable:opcodename
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: execute_action: DYNACODE opcode:delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_ao: OPCODE delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [apiInterface:6135]: do_ao: OPCODE delete_AUTH_server CONTENT-TYPE:json, BODY_LEN:398
    DEBUG     Feb 09 10:40:45  [listener:1015]: ln_recvfrom: fd '111.TCP.INET.auxilary': 486 bytes are read by listener
    DEBUG     Feb 09 10:40:45  [listener:1015]: register_request_inet: request from port '0'
    INFO      Feb 09 10:40:45  [listener:1015]: Assigning free worker 6079
    DEBUG     Feb 09 10:40:45  [listener:1015]: assign_to_busy_queue: assigning worker 6079
    DEBUG     Feb 09 10:40:45  [listener:1015]: send_data_to_sockpair: listener has send 450 bytes to sockpair worker 6079
    DEBUG     Feb 09 10:40:45  [worker:6079]: read_packet: read() 450 bytes from listener
    DEBUG     Feb 09 10:40:45  [worker:6079]: # OPCODE Called: 'delete_AUTH_server'
    MESSAGE   Feb 09 10:40:45  [worker:6079]: {"request":{"method":"opcode","name":"delete_AUTH_server","version":"1.14","type":"json","length":398,"data":{ "Event": "DELETE", "select": [ "DNS-SRV" ], "adsserverids": "DNS-SRV", "___serverprotocol": "HTTP", "___component": "GUI", "Entity": "adsserver", "___username": "admin", "mode": 473, "___meta": { "sessionType": 1 }, "___serverport": 4444, "currentlyloggedinuserip": "192.168.222.36", "___serverip": "192.168.222.253", "APIVersion": "1800.2", "transactionid": "412", "currentlyloggedinuserid": 3 }}}
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: hdr: len=398 content=0 method=0 name=delete_AUTH_server
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: skipping uuid insertion
    DEBUG     Feb 09 10:40:45  [worker:6079]: ### insert_uuid: uuid insertion took 0 s 24665 ns
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: creating json object
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: Initializing database handle
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(serverid || ','),0,length(mergetext(serverid || ','))) as serverid from tblradiusauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.id || ','),0,length(mergetext(a.id || ','))) as serverid from tbltacacsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.serverid || ','),0,length(mergetext(a.serverid || ','))) as serverid from tbladsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid and a.servertype=1'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "1" ] }
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_query: Query: 'select substr(mergetext(a.serverid || ','),0,length(mergetext(a.serverid || ','))) as serverid from tbladsauthserver a, tblauthserverconfig b where b.name in ('DNS-SRV') and b.id = a.authserverid and a.servertype=2'
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: out.status=0
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: create_act_out_perl_obj: JSON out.output={ "serverid": [ "" ] }
    INFO      Feb 09 10:40:45  [delete_AUTH_server:6079]: ACTION: CALL add_extra_pera
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_ao: OPCODE apiInterface
    DEBUG     Feb 09 10:40:45  [delete_AUTH_server:6079]: do_ao: OPCODE apiInterface CONTENT-TYPE:json, BODY_LEN:176
    DEBUG     Feb 09 10:40:45  [listener:1015]: ln_recvfrom: fd '5.UDP.INET.server': 258 bytes are read by listener
    DEBUG     Feb 09 10:40:45  [listener:1015]: register_request_inet: request from port '56305'
    INFO      Feb 09 10:40:45  [listener:1015]: Assigning free worker 6078
    DEBUG     Feb 09 10:40:45  [listener:1015]: assign_to_busy_queue: assigning worker 6078
    DEBUG     Feb 09 10:40:45  [listener:1015]: send_data_to_sockpair: listener has send 228 bytes to sockpair worker 6078
    DEBUG     Feb 09 10:40:45  [worker:6078]: read_packet: read() 228 bytes from listener
    DEBUG     Feb 09 10:40:45  [worker:6078]: # OPCODE Called: 'apiInterface'
    MESSAGE   Feb 09 10:40:45  [worker:6078]: {"request":{"method":"opcode","name":"apiInterface","version":"1.14","type":"json","length":176,"data":{ "___caller": "system", "___username": "admin", "serverid": [ "1" ], "currentlyloggedinuserip": "192.168.222.36", "mode": "19", "APIVersion": "1500.1", "___component": "GUI" }}}
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: hdr: len=176 content=0 method=0 name=apiInterface
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: skipping uuid insertion because empty '"autogen_uuid"' not found in body
    DEBUG     Feb 09 10:40:45  [worker:6078]: ### insert_uuid: uuid insertion took 0 s 29490 ns
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:45  [apiInterface:6078]: creating json object
    INFO      Feb 09 10:40:45  [apiInterface:6078]: ACTION: CALL sanitizeRequest
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:45  [apiInterface:6078]: do_log_to_file: length=72
    INFO      Feb 09 10:40:45  [apiInterface:6078]: ACTION: CALL variableInitialization
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: Initializing database handle
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: Txid:468033
    INFO      Feb 09 10:40:46  [apiInterface:6078]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'start transaction'
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=17
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL isAPIVersionSupported
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=37
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL opcodePreProcess
    INFO      Feb 09 10:40:46  [apiInterface:6078]: executing FORLOOP
    INFO      Feb 09 10:40:46  [apiInterface:6078]: FORLOOP condition true
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL checkUserPermission
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select userid from tbluser where username= '$currentUser''
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=curLogOut
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: curLogOut.status=0
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select entityid from tblcrevent where mode  = $request->{mode}'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL preMigration
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL createModeJSON
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=33
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL migrateToCurrVersion
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=38
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL createJson
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL validateJson
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=32
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL handleDeleteRequest
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL replyIfErrorAtValidation
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL getOldObject
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'select opcode,opcodetype,perlpackagename from tblcrevent where mode=$request->{mode}'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=opout
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: opout.status=0
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: logger: applog
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_log_to_file: length=136
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: execute_action: DYNACODE variable:opcodename
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: execute_action: DYNACODE opcode:delete_ADS_server
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_ao: OPCODE delete_ADS_server
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_ao: OPCODE delete_ADS_server CONTENT-TYPE:json, BODY_LEN:206
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_recvfrom: fd '112.TCP.INET.auxilary': 293 bytes are read by listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: register_request_inet: request from port '0'
    INFO      Feb 09 10:40:46  [listener:1015]: Assigning free worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: assign_to_busy_queue: assigning worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: send_data_to_sockpair: listener has send 258 bytes to sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [worker:6077]: read_packet: read() 258 bytes from listener
    DEBUG     Feb 09 10:40:46  [worker:6077]: # OPCODE Called: 'delete_ADS_server'
    MESSAGE   Feb 09 10:40:46  [worker:6077]: {"request":{"method":"opcode","name":"delete_ADS_server","version":"1.14","type":"json","length":206,"data":{ "___component": "GUI", "mode": "19", "currentlyloggedinuserip": "192.168.222.36", "serverid": [ "1" ], "currentlyloggedinuserid": 3, "___caller": "system", "___username": "admin", "APIVersion": "1500.1" }}}
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: hdr: len=206 content=0 method=0 name=delete_ADS_server
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: skipping uuid insertion
    DEBUG     Feb 09 10:40:46  [worker:6077]: ### insert_uuid: uuid insertion took 0 s 24835 ns
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: init_db_handle_pl: Initializing DBI DB handle
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: creating json object
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: Initializing database handle
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQexec, result not NULL
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQexec, result2 not NULL
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: Txid:468034
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: csc_query: After PQclear
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'start transaction'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: ACTION: CALL delete_LDAP_and_ADS_server
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=16
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: traversing scalar 'serverid' over 'serverids'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select count(*) as count from tblauthsettings where authserverid = (select authserverid from tbladsauthserver where serverid=$serverid)'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=resultq
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: resultq.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=46
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_log_to_file: length=8
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select servertype,authserverid from tbladsauthserver where serverid =$serverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: result.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select name from tblauthserverconfig where id=$authserverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=authServerName
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: authServerName.status=0
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'select serverdomainrelid from tbladsserverdomainrel where serverid = $serverid'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: varname=result
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: create_act_out_perl_obj: result.status=0
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: traversing scalar 'domainid' over 'domainids'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsdomainsearchqueryrel where serverdomainrelid=$domainid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsserverdomainrel where serverid = $serverid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'delete from tbladsauthserver where serverid = $serverid'
    ERROR     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Failed Query: 'delete from tblauthserverconfig where id=$authserverid'
    DEBUG     Feb 09 10:40:46  [delete_ADS_server:6077]: do_query: Query: 'rollback'
    INFO      Feb 09 10:40:46  [delete_ADS_server:6077]: opcode 'delete_ADS_server': time taken: 0.274450545 seconds
    DEBUG     Feb 09 10:40:46  [worker:6077]: # OPCODE Exited: 'delete_ADS_server' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6077]: write_packet: 52+6+2
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 60 bytes read from sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6077
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '112.TCP.INET.auxilary' has sent 40 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6077 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6077 is removed from busy list
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: out.status=500
    INFO      Feb 09 10:40:46  [apiInterface:6078]: create_act_out_perl_obj: out.error=OK
    DEBUG     Feb 09 10:40:46  [apiInterface:6078]: do_query: Query: 'rollback'
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: CALL replyFailureMessage
    INFO      Feb 09 10:40:46  [apiInterface:6078]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [apiInterface:6078]: json_tokener_parse: invalid json string: 'failed'

     PAckage ::::cscvalidation/identity/AuthenticationServer.plDEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6077, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BD1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 113
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6165
    DEBUG     Feb 09 10:40:46  [listener:1015]: release_fd_struct: fd '112.TCP.INET.auxilary' is closed
    INFO      Feb 09 10:40:46  [apiInterface:6078]: opcode 'apiInterface': time taken: 0.673379274 seconds
    DEBUG     Feb 09 10:40:46  [worker:6078]: # OPCODE Exited: 'apiInterface' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6078]: write_packet: 52+0+13
    DEBUG     Feb 09 10:40:46  [worker:6078]: write_packet: write 65 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 65 bytes read from sockpair worker 6078
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6078
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '5.UDP.INET.server' has sent 28 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6078 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6078 is removed from busy list
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: varname=adsserverout
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: adsserverout.status=500
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: create_act_out_perl_obj: adsserverout.error=Opcode Failed
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_log_to_file: length=13
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [delete_AUTH_server:6079]: get_string_from_var : 'response' is not a string
    ERROR     Feb 09 10:40:46  [delete_AUTH_server:6079]: json_tokener_parse: invalid json string: 'response'
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: logger: applog
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_log_to_file: length=13
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: CALL LOG_MESSAGE
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: ACTION: DLOPEN(get_time, (null))
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: ws_do_evlog: FD: 4
    DEBUG     Feb 09 10:40:46  [delete_AUTH_server:6079]: do_evlog_to_file: FD: 4
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6078, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BE1700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 112
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6170
    INFO      Feb 09 10:40:46  [delete_AUTH_server:6079]: opcode 'delete_AUTH_server': time taken: 0.950426280 seconds
    DEBUG     Feb 09 10:40:46  [worker:6079]: {"response":{"method":"opcode","name":"delete_AUTH_server","version":"1.14","type":"text","length":0,"statusCode":200,"statusStrlen":2,"statusString":"OK"}}
    DEBUG     Feb 09 10:40:46  [worker:6079]: # OPCODE Exited: 'delete_AUTH_server' with Status: '200'
    DEBUG     Feb 09 10:40:46  [worker:6079]: write_packet: 52+0+2
    DEBUG     Feb 09 10:40:46  [worker:6079]: write_packet: write 54 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 54 bytes read from sockpair worker 6079
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6079
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '111.TCP.INET.auxilary' has sent 17 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6079 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6079 is removed from busy list
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: varname=out
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: out.status=200
    INFO      Feb 09 10:40:46  [apiInterface:6135]: create_act_out_perl_obj: out.error=OK
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition false
    DEBUG     Feb 09 10:40:46  [apiInterface:6135]: do_query: Query: 'commit'
    INFO      Feb 09 10:40:46  [apiInterface:6135]: executing FORLOOP
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition true
    INFO      Feb 09 10:40:46  [apiInterface:6135]: FORLOOP condition false
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: CALL generateAuditLog
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: CALL replySuccessMessage
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6079, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  BF1700} data:{ 5, 4,  1000} , 27}
    INFO      Feb 09 10:40:46  [apiInterface:6135]: ACTION: DLOPEN(json2hash, response)
    ERROR     Feb 09 10:40:46  [apiInterface:6135]: get_string_from_var : 'response' is not a string
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 112
    ERROR     Feb 09 10:40:46  [apiInterface:6135]: json_tokener_parse: invalid json string: 'response'

     PAckage ::::cscvalidation/identity/AuthenticationServer.plDEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6171
    DEBUG     Feb 09 10:40:46  [listener:1015]: release_fd_struct: fd '111.TCP.INET.auxilary' is closed
    INFO      Feb 09 10:40:46  [apiInterface:6135]: opcode 'apiInterface': time taken: 1.417621691 seconds
    DEBUG     Feb 09 10:40:46  [worker:6135]: worker_proc: going to release dbhandle for 6135(1,613501)
    DEBUG     Feb 09 10:40:46  [worker:6135]: Main TLV:{ 4, data:{ 1, 4,  7D5C90} data:{ 2, 4,  F71700} data:{ 5, 4,  0000} , 27}
    DEBUG     Feb 09 10:40:46  [worker:6135]: {"response":{"method":"opcode","name":"apiInterface","version":"1.8","type":"text","length":0,"statusCode":500,"statusStrlen":13,"statusString":"Opcode Failed"}}
    DEBUG     Feb 09 10:40:46  [worker:6135]: # OPCODE Exited: 'apiInterface' with Status: '500'
    DEBUG     Feb 09 10:40:46  [worker:6135]: write_packet: 52+0+13
    DEBUG     Feb 09 10:40:46  [worker:6135]: write_packet: write 65 bytes to listener
    DEBUG     Feb 09 10:40:46  [listener:1015]: read_response_from_sockpair: 65 bytes read from sockpair worker 6135
    DEBUG     Feb 09 10:40:46  [listener:1015]: is_response_complete: Complete response is received from sockpair worker 6135
    DEBUG     Feb 09 10:40:46  [listener:1015]: Received response from worker
    DEBUG     Feb 09 10:40:46  [listener:1015]: ln_sendto: fd '5.UDP.INET.server' has sent 27 bytes to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Listener has sent data to requester
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker with pid 6135 got executed, will revive again.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Worker 6135 is removed from busy list
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_waitpid: Process with pid 6135, wrapped-up successfully using signal 9.
    DEBUG     Feb 09 10:40:46  [listener:1015]: Main TLV:{ 4, data:{ 1, 4,  0000} data:{ 2, 4,  F71700} data:{ 5, 4,  1000} , 27}
    DEBUG     Feb 09 10:40:46  [listener:1015]: csc_socketpair called: biggest fd is 111
    DEBUG     Feb 09 10:40:46  [listener:1015]: Realising worker 6172

Children
No Data