Thread Info
  • State Not Answered
  • Replies 3 replies
  • Subscribers 14 subscribers
  • Views 78 views
  • Users 0 members are here
Options
Suggested

User Portal Reattempting the login page.

lokesh pardeshi
2 days ago

Hi, 

I have Sophos XG230 F/W. We have configured the SSL VPN. When we trying to login user portal to download the VPN client it's reattempting the login page and not login inside.  It was working till fine till yesterday but suddenly we can not able to login on user portal. 

Same user credentials are working fine to connect the VPN but not able to login user portal. After entering the username and password its redirecting the login page again. 

Thanks

Lokesh

  • 0 2 days ago

    Hi ,

    Thanks for reaching out, and welcome to the Sophos Community! 

    What is the firmware version on your firewall? Are you having this issue with local users or AD users? 

    Would it be possible for you to put the access_server process in debugging and provide the debug logs via personal message? 

    Follow this knowledge base Article to SSH into the XG firewall: Sophos XG Firewall: How to SSH to the firewall using PuTTY utility

    • Select Option 5 (Device Management) > Option 3 (Advance Shell)

    Run this command to put the access_server service in debug:

    • service access_server:debug -d -s nosync

    Please check out the following KBA to locate and capture the logs: Sophos XG Firewall: Where to find log files?

    Once you capture the access_server logs in debugging, run the same command to put the access_server service in normal running mode. 

    Run this command to check service status :

    •  service -S | grep access_server

    SFVUNL_VM01_SFOS 17.5.11 MR-11# service -S | grep access_server
    access_server RUNNING,DEBUG

    Please PM me the logs and username. 

    Thanks,

     
     
    Harsh Patel (H_Patel)

    Community Support Engineer | Sophos Technical Support
    Support Videos | Product Documentation | @SophosSupport | Sign up for SMS Alerts
    If a post solves your question use the 'Verify Answer' button.

  • 0 2 days ago in reply to H_Patel

    Dear Harsh,

    Thanks for your reply. 

    Here are the details - 

    1) We are having this issue with local user (Not AD user)

    2) User Name - lokesh.pardeshi (All the users are having the same issue) 

    3) Logs - 

    XG230_WP02_SFOS 18.0.4 MR-4# tail -f /log/access_server.log
    INFO Apr 09 08:49:04.699264 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=24 wq=0x578bf5d0 buf=0x578bf5d8 offset=0
    DEBUG Apr 09 08:49:04.699268 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:49:04.699275 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 25
    DEBUG Apr 09 08:49:04.699279 [EDIR_SYNC]: handle_server_events: EVENT_READ
    INFO Apr 09 08:49:04.699282 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:49:04.699287 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=25
    DEBUG Apr 09 08:49:04.699291 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x578bf378 req_handler=0x5668e1ad type=0 handler_data=(nil) res_handler=(nil)
    INFO Apr 09 08:49:04.699296 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:49:04.699300 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
    INFO Apr 09 08:49:04.699303 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
    DEBUG Apr 09 08:49:20.338524 [CAA]: (CA_epoll_wait): returning 0
    MESSAGE Apr 09 08:49:20.338570 [CAA]: (CA_keep_alive): access_server heartbeat
    DEBUG Apr 09 08:49:20.338575 [CAA]: (CA_keep_alive): Checking connections status
    MESSAGE Apr 09 08:49:20.338579 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
    DEBUG Apr 09 08:49:20.338582 [CAA]: (process_caa_messages): Waiting for CAA events
    DEBUG Apr 09 08:49:20.338586 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
    DEBUG Apr 09 08:49:41.960753 [access_server]: (handle_client): 63 bytes from IP: 127.0.0.1, PORT: 45919
    DEBUG Apr 09 08:49:41.960767 [access_server]: (handle_client): pktinfo: ifindex: 1, local address: 127.0.0.1
    DEBUG Apr 09 08:49:41.960786 [access_server]: (handle_client): Received request length in TLV = 63. Received bytes on socket = 63. tlv_jump = 0.


    INFO Apr 09 08:49:41.960791 [access_server]: process_request: Request Code:91
    DEBUG Apr 09 08:49:41.960794 [access_server]: more_tlv_checks : current tlv len = 4 Sum of length of sub tlv = 8

    DEBUG Apr 09 08:49:41.960798 [access_server]: more_tlv_checks : current tlv len = 16 Sum of length of sub tlv = 28

    DEBUG Apr 09 08:49:41.960801 [access_server]: more_tlv_checks : current tlv len = 12 Sum of length of sub tlv = 44

    DEBUG Apr 09 08:49:41.960804 [access_server]: more_tlv_checks : current tlv len = 10 Sum of length of sub tlv = 58

    DEBUG Apr 09 08:49:41.960808 [access_server]: more_tlv_checks : Valid TLV received, Length of main TLV = 63 Sum of length of sub tlv = 58
    INFO Apr 09 08:49:41.960817 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Apr 09 08:49:41.960820 [access_server]: print_auth_tlv: TLV Type: 0
    INFO Apr 09 08:49:41.960824 [access_server]: print_auth_tlv: TLV Length: 4
    INFO Apr 09 08:49:41.960827 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Apr 09 08:49:41.960830 [access_server]: (process_pam_request): clienttype:'10'
    INFO Apr 09 08:49:41.960833 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Apr 09 08:49:41.960837 [access_server]: print_auth_tlv: TLV Type: 1
    INFO Apr 09 08:49:41.960840 [access_server]: print_auth_tlv: TLV Length: 16
    INFO Apr 09 08:49:41.960843 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Apr 09 08:49:41.960846 [access_server]: (process_pam_request): username:'lokesh.pardeshi'
    INFO Apr 09 08:49:41.960849 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Apr 09 08:49:41.960853 [access_server]: print_auth_tlv: TLV Type: 2
    INFO Apr 09 08:49:41.960856 [access_server]: print_auth_tlv: TLV Length: 12
    INFO Apr 09 08:49:41.960859 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Apr 09 08:49:41.960862 [access_server]: (process_pam_request): password: not empty
    INFO Apr 09 08:49:41.960865 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Apr 09 08:49:41.960868 [access_server]: print_auth_tlv: TLV Type: 5
    INFO Apr 09 08:49:41.960871 [access_server]: print_auth_tlv: TLV Length: 10
    INFO Apr 09 08:49:41.960875 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Apr 09 08:49:41.960878 [access_server]: (process_pam_request): ipaddress:'127.0.0.1'
    DEBUG Apr 09 08:49:41.960888 [access_server]: (lc_utf8_bytes): lowercase = 'lokesh.pardeshi'
    DEBUG Apr 09 08:49:41.960893 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=35 req_handler=0x5666dc51 res_handler=0x5664f8c9 handler_data=0x578e93e0
    DEBUG Apr 09 08:49:41.960897 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:49:41.960900 [access_server]: (append_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.960905 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:49:41.960908 [access_server]: (append_subsysqueue): released lock 0x578238a8
    INFO Apr 09 08:49:41.960911 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.960915 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=35
    DEBUG Apr 09 08:49:41.960919 [access_server]: (write_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.960926 [access_server]: (write_subsysqueue): released lock 0x578238a8
    INFO Apr 09 08:49:41.960929 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x578330e0 buf=0x578330e8 offset=0
    DEBUG Apr 09 08:49:41.960938 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:49:41.960938 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
    DEBUG Apr 09 08:49:41.960954 [POSTGRES_DB]: handle_server_events: EVENT_READ
    INFO Apr 09 08:49:41.960958 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Apr 09 08:49:41.960964 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
    DEBUG Apr 09 08:49:41.960968 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x57832ed8 req_handler=0x5666dc51 type=35 handler_data=0x578e93e0 res_handler=0x5664f8c9
    DEBUG Apr 09 08:49:41.960972 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:49:41.960976 [POSTGRES_DB]: (pg_db_handle_request): AUTHENTICATE_GUEST_USER triggers alloc_query_vals()
    DEBUG Apr 09 08:49:41.960980 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
    DEBUG Apr 09 08:49:41.960984 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'AUTHENTICATE_GUEST_USER'
    DEBUG Apr 09 08:49:41.960987 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
    DEBUG Apr 09 08:49:41.960991 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'lokesh.pardeshi'
    DEBUG Apr 09 08:49:41.961463 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'AUTHENTICATE_GUEST_USER'
    DEBUG Apr 09 08:49:41.961469 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf6f76580)
    DEBUG Apr 09 08:49:41.961474 [POSTGRES_DB]: pg_db_handle_authenticate_guest_user: row count: 1
    DEBUG Apr 09 08:49:41.961477 [POSTGRES_DB]: pg_db_handle_authenticate_guest_user: column:'usertype', value:'1'
    DEBUG Apr 09 08:49:41.961481 [POSTGRES_DB]: pg_db_handle_authenticate_guest_user: Not a Guest user
    DEBUG Apr 09 08:49:41.961485 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0
    DEBUG Apr 09 08:49:41.961488 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:49:41.961492 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.961495 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:49:41.961499 [POSTGRES_DB]: (append_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.961502 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961506 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0
    DEBUG Apr 09 08:49:41.961509 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.961515 [POSTGRES_DB]: (write_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.961520 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x57832f80 buf=0x57832f88 offset=0
    DEBUG Apr 09 08:49:41.961519 [access_server]: handle_client_events: EVENT_READ
    INFO Apr 09 08:49:41.961524 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Apr 09 08:49:41.961526 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.961528 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
    INFO Apr 09 08:49:41.961533 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
    INFO Apr 09 08:49:41.961535 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
    DEBUG Apr 09 08:49:41.961537 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x57833038 req_handler=(nil) type=0 handler_data=0x578e93e0 res_handler=0x5664f8c9
    DEBUG Apr 09 08:49:41.961542 [access_server]: (subsys_submit_request): subsys_name=OTP_AUTH req_type=0 req_handler=0x566a478b res_handler=0x5664ef1f handler_data=0x578e93e0
    DEBUG Apr 09 08:49:41.961546 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:49:41.961549 [access_server]: (append_subsysqueue): acquiring lock 0x578a6038
    DEBUG Apr 09 08:49:41.961554 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:49:41.961558 [access_server]: (append_subsysqueue): released lock 0x578a6038
    INFO Apr 09 08:49:41.961566 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961570 [access_server]: (subsys_submit_request): OTP_AUTH: request submitted, req_type=0
    DEBUG Apr 09 08:49:41.961573 [access_server]: (write_subsysqueue): acquiring lock 0x578a6038
    DEBUG Apr 09 08:49:41.961580 [access_server]: (write_subsysqueue): released lock 0x578a6038
    DEBUG Apr 09 08:49:41.961585 [OTP_AUTH]: subsys_thread_main: OTP_AUTH: event received on fd: 16
    INFO Apr 09 08:49:41.961587 [access_server]: (write_subsysqueue): OTP_AUTH CLIENT: written 16 bytes, fd=15 wq=0x578a5e30 buf=0x578a5e38 offset=0
    DEBUG Apr 09 08:49:41.961590 [OTP_AUTH]: handle_server_events: EVENT_READ
    INFO Apr 09 08:49:41.961591 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.961593 [OTP_AUTH]: (do_handle_read): OTP_AUTH server: READING... fd=16
    INFO Apr 09 08:49:41.961596 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
    INFO Apr 09 08:49:41.961599 [OTP_AUTH]: (do_handle_read): OTP_AUTH server: read 16 bytes, fd=16
    DEBUG Apr 09 08:49:41.961600 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:49:41.961603 [OTP_AUTH]: (do_handle_read): OTP_AUTH server tlv=0x578a6618 req_handler=0x566a478b type=0 handler_data=0x578e93e0 res_handler=0x5664ef1f
    DEBUG Apr 09 08:49:41.961607 [OTP_AUTH]: (otp_handle_prepare_authentication_request): OTP prepare authentication for user lokesh.pardeshi
    DEBUG Apr 09 08:49:41.961611 [OTP_AUTH]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:49:41.961614 [OTP_AUTH]: (append_subsysqueue): acquiring lock 0x578a605c
    DEBUG Apr 09 08:49:41.961617 [OTP_AUTH]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:49:41.961621 [OTP_AUTH]: (append_subsysqueue): released lock 0x578a605c
    INFO Apr 09 08:49:41.961624 [OTP_AUTH]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961627 [OTP_AUTH]: subsys_submit_response: OTP_AUTH: response submitted, res_type=0
    DEBUG Apr 09 08:49:41.961631 [OTP_AUTH]: (write_subsysqueue): acquiring lock 0x578a605c
    DEBUG Apr 09 08:49:41.961635 [OTP_AUTH]: (write_subsysqueue): released lock 0x578a605c
    DEBUG Apr 09 08:49:41.961636 [access_server]: handle_client_events: EVENT_READ
    INFO Apr 09 08:49:41.961638 [OTP_AUTH]: (write_subsysqueue): OTP_AUTH SERVER: written 16 bytes, fd=16 wq=0x578a62c0 buf=0x578a62c8 offset=0
    INFO Apr 09 08:49:41.961640 [access_server]: (do_handle_read): OTP_AUTH client: READING... fd=15
    INFO Apr 09 08:49:41.961643 [OTP_AUTH]: (do_handle_read): OTP_AUTH server: READING... fd=16
    INFO Apr 09 08:49:41.961645 [access_server]: (do_handle_read): OTP_AUTH client: read 16 bytes, fd=15
    INFO Apr 09 08:49:41.961647 [OTP_AUTH]: (do_handle_read): OTP_AUTH server: read blocked
    DEBUG Apr 09 08:49:41.961648 [access_server]: (do_handle_read): OTP_AUTH client tlv=0x578a5d88 req_handler=(nil) type=0 handler_data=0x578e93e0 res_handler=0x5664ef1f
    INFO Apr 09 08:49:41.961650 [OTP_AUTH]: subsys_thread_main: OTP_AUTH: waiting for events...
    DEBUG Apr 09 08:49:41.961652 [access_server]: (authenticate_user): current server:0, auth_client:7
    INFO Apr 09 08:49:41.961656 [access_server]: authenticate_user: Server:0, Local Authentication
    DEBUG Apr 09 08:49:41.961660 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=36 req_handler=0x5666dc51 res_handler=0x5664ef1f handler_data=0x578e93e0
    DEBUG Apr 09 08:49:41.961663 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:49:41.961667 [access_server]: (append_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.961670 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:49:41.961673 [access_server]: (append_subsysqueue): released lock 0x578238a8
    INFO Apr 09 08:49:41.961676 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961683 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=36
    DEBUG Apr 09 08:49:41.961686 [access_server]: (write_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.961691 [access_server]: (write_subsysqueue): released lock 0x578238a8
    DEBUG Apr 09 08:49:41.961692 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
    INFO Apr 09 08:49:41.961694 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x578330e0 buf=0x578330e8 offset=0
    DEBUG Apr 09 08:49:41.961696 [POSTGRES_DB]: handle_server_events: EVENT_READ
    INFO Apr 09 08:49:41.961698 [access_server]: (do_handle_read): OTP_AUTH client: READING... fd=15
    INFO Apr 09 08:49:41.961699 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Apr 09 08:49:41.961702 [access_server]: (do_handle_read): OTP_AUTH client: read blocked
    INFO Apr 09 08:49:41.961704 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
    DEBUG Apr 09 08:49:41.961706 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:49:41.961708 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x57832ed8 req_handler=0x5666dc51 type=36 handler_data=0x578e93e0 res_handler=0x5664ef1f
    DEBUG Apr 09 08:49:41.961712 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:49:41.961715 [POSTGRES_DB]: (pg_db_handle_request): AUTHENTICATE_USER triggers alloc_query_vals()
    DEBUG Apr 09 08:49:41.961719 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
    DEBUG Apr 09 08:49:41.961722 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'AUTHENTICATE_USER'
    DEBUG Apr 09 08:49:41.961726 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
    DEBUG Apr 09 08:49:41.961729 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0] length=4: 1
    DEBUG Apr 09 08:49:41.961733 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1] length=4: 5
    DEBUG Apr 09 08:49:41.961736 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2] length=4: 2
    DEBUG Apr 09 08:49:41.961739 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[3] length=4: 1
    DEBUG Apr 09 08:49:41.961743 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[4]: 'lokesh.pardeshi'
    DEBUG Apr 09 08:49:41.961821 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'AUTHENTICATE_USER'
    DEBUG Apr 09 08:49:41.961825 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf6f76580)
    DEBUG Apr 09 08:49:41.961829 [POSTGRES_DB]: (pg_db_handle_authenticate_user): row count: 1
    DEBUG Apr 09 08:49:41.961835 [POSTGRES_DB]: (lc_utf8_bytes): lowercase = 'lokesh.pardeshi'
    DEBUG Apr 09 08:49:41.961839 [POSTGRES_DB]: (get_contextid): contextid:tbluser:lokesh.pardeshi
    DEBUG Apr 09 08:49:41.961874 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0
    DEBUG Apr 09 08:49:41.961878 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:49:41.961881 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.961884 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:49:41.961888 [POSTGRES_DB]: (append_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.961891 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961894 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0
    DEBUG Apr 09 08:49:41.961897 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.961902 [POSTGRES_DB]: (write_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.961906 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x57832f80 buf=0x57832f88 offset=0
    INFO Apr 09 08:49:41.961909 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    DEBUG Apr 09 08:49:41.961909 [access_server]: handle_client_events: EVENT_READ
    INFO Apr 09 08:49:41.961918 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
    INFO Apr 09 08:49:41.961920 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.961922 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
    INFO Apr 09 08:49:41.961925 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
    DEBUG Apr 09 08:49:41.961928 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x57833038 req_handler=(nil) type=0 handler_data=0x578e93e0 res_handler=0x5664ef1f
    DEBUG Apr 09 08:49:41.961932 [access_server]: (authenticate_user): current server:1, auth_client:7
    DEBUG Apr 09 08:49:41.961935 [access_server]: authenticate_user: SUCCESS || current_server >= MAX_LIMIT
    DEBUG Apr 09 08:49:41.961939 [access_server]: (is_local_auth): current_server = 0, auth_client = 7, authserver_id = 1, local_authserver_id = 1
    DEBUG Apr 09 08:49:41.961943 [access_server]: (check_auth_result): lokesh.pardeshi ==> local user
    DEBUG Apr 09 08:49:41.961946 [access_server]: check_auth_result: Authentication Successful, clienttype=10 auth_client=7
    DEBUG Apr 09 08:49:41.961950 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=39 req_handler=0x5666dc51 res_handler=0x5664ca7a handler_data=0x578e93e0
    DEBUG Apr 09 08:49:41.961954 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:49:41.961957 [access_server]: (append_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.961960 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:49:41.961964 [access_server]: (append_subsysqueue): released lock 0x578238a8
    INFO Apr 09 08:49:41.961967 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.961970 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=39
    DEBUG Apr 09 08:49:41.961973 [access_server]: (write_subsysqueue): acquiring lock 0x578238a8
    DEBUG Apr 09 08:49:41.961978 [access_server]: (write_subsysqueue): released lock 0x578238a8
    DEBUG Apr 09 08:49:41.961980 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
    INFO Apr 09 08:49:41.961981 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x578330e0 buf=0x578330e8 offset=0
    DEBUG Apr 09 08:49:41.961984 [POSTGRES_DB]: handle_server_events: EVENT_READ
    INFO Apr 09 08:49:41.961986 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.961987 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Apr 09 08:49:41.961990 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
    INFO Apr 09 08:49:41.961992 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
    DEBUG Apr 09 08:49:41.961993 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:49:41.961996 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x57832ed8 req_handler=0x5666dc51 type=39 handler_data=0x578e93e0 res_handler=0x5664ca7a
    DEBUG Apr 09 08:49:41.962000 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:49:41.962004 [POSTGRES_DB]: (pg_db_handle_request): MYACCOUNT_USER triggers alloc_query_vals()
    DEBUG Apr 09 08:49:41.962007 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
    DEBUG Apr 09 08:49:41.962010 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'MYACCOUNT_USER'
    DEBUG Apr 09 08:49:41.962014 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
    DEBUG Apr 09 08:49:41.962017 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'lokesh.pardeshi'
    DEBUG Apr 09 08:49:41.962021 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1] length=4: 1
    DEBUG Apr 09 08:49:41.962024 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2] length=4: 5
    DEBUG Apr 09 08:49:41.962030 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[3] length=4: 2
    DEBUG Apr 09 08:49:41.962033 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[4] length=4: 8
    DEBUG Apr 09 08:49:41.962131 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'MYACCOUNT_USER'
    DEBUG Apr 09 08:49:41.962135 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf6f76580)
    DEBUG Apr 09 08:49:41.962139 [POSTGRES_DB]: pg_db_handle_xauth_user: row count: 1
    DEBUG Apr 09 08:49:41.962143 [POSTGRES_DB]: pg_db_handle_xauth_user: column:'count', value:'1'
    DEBUG Apr 09 08:49:41.962146 [POSTGRES_DB]: pg_db_handle_xauth_user: result_code=2
    DEBUG Apr 09 08:49:41.962150 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0
    DEBUG Apr 09 08:49:41.962153 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:49:41.962156 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.962160 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:49:41.962163 [POSTGRES_DB]: (append_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.962166 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:49:41.962169 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0
    DEBUG Apr 09 08:49:41.962173 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x578238cc
    DEBUG Apr 09 08:49:41.962177 [POSTGRES_DB]: (write_subsysqueue): released lock 0x578238cc
    INFO Apr 09 08:49:41.962181 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x57832f80 buf=0x57832f88 offset=0
    DEBUG Apr 09 08:49:41.962180 [access_server]: handle_client_events: EVENT_READ
    INFO Apr 09 08:49:41.962184 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Apr 09 08:49:41.962186 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.962189 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
    INFO Apr 09 08:49:41.962191 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
    INFO Apr 09 08:49:41.962192 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
    DEBUG Apr 09 08:49:41.962195 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x57833038 req_handler=(nil) type=0 handler_data=0x578e93e0 res_handler=0x5664ca7a
    DEBUG Apr 09 08:49:41.962199 [access_server]: (delete_admin_access_entry): invoked
    DEBUG Apr 09 08:49:41.962203 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:49:41.962207 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xff95f368 for query 0x5676f928
    DEBUG Apr 09 08:49:41.962211 [access_server]: (bind_parameters_to_statement): Query name IS_ADMIN_IP_EXIST
    DEBUG Apr 09 08:49:41.962221 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(IS_ADMIN_IP_EXIST, 127.0.0.1) succeeded
    DEBUG Apr 09 08:49:41.962234 [access_server]: (handle_count_star_query): IS_ADMIN_IP_EXIST retrieved: count = 0
    DEBUG Apr 09 08:49:41.962239 [access_server]: (handle_count_star_query): returning 0
    DEBUG Apr 09 08:49:41.962243 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:49:41.962247 [access_server]: (handle_pam_authorization): VPN/SSLVPN/MYACC Authorization Successful
    DEBUG Apr 09 08:49:41.962250 [access_server]: (send_pam_response): resp_code=2, clienttype=10, message=''
    DEBUG Apr 09 08:49:41.962254 [access_server]: send_pam_response: message:'', len:0, data:''
    DEBUG Apr 09 08:49:41.962257 [access_server]: (send_response_authtlv): Packetlen:4
    DEBUG Apr 09 08:49:41.962262 [access_server]: (do_sendto): send response of 4 bytes to IP: 127.0.0.1 PORT: 45919
    DEBUG Apr 09 08:49:41.962266 [access_server]: (do_sendto): pktinfo: ifindex: 0, local address: 127.0.0.1
    DEBUG Apr 09 08:49:41.962277 [access_server]: (send_response_authtlv): Bytes sent:4, Buf len:4
    DEBUG Apr 09 08:49:41.962287 [access_server]: (fill_pam_garner_data): AF_INET ip address '127.0.0.1' is valid
    DEBUG Apr 09 08:49:41.962296 [access_server]: free_session_data: session_data=0x578e93e0
    INFO Apr 09 08:49:41.962300 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Apr 09 08:49:41.962304 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
    DEBUG Apr 09 08:49:41.962308 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:50:03.833337 [access_server]: tlvserver_handle_request: tlv request received
    INFO Apr 09 08:50:03.833355 [access_server]: tlvserver_print_request: ---------------------------------
    INFO Apr 09 08:50:03.833359 [access_server]: tlvserver_print_request: TLV ID: 140
    INFO Apr 09 08:50:03.833362 [access_server]: tlvserver_print_request: TLV Type: 0
    INFO Apr 09 08:50:03.833365 [access_server]: tlvserver_print_request: TLV Length: 0
    INFO Apr 09 08:50:03.833369 [access_server]: tlvserver_print_request: TLV Cl Res: 0
    INFO Apr 09 08:50:03.833372 [access_server]: tlvserver_print_request: ---------------------------------
    MESSAGE Apr 09 08:50:03.833375 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
    DEBUG Apr 09 08:50:03.833379 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:50:04.834251 [access_server]: tlvserver_handle_request: tlv request received
    INFO Apr 09 08:50:04.834266 [access_server]: tlvserver_print_request: ---------------------------------
    INFO Apr 09 08:50:04.834270 [access_server]: tlvserver_print_request: TLV ID: 148
    INFO Apr 09 08:50:04.834273 [access_server]: tlvserver_print_request: TLV Type: 0
    INFO Apr 09 08:50:04.834276 [access_server]: tlvserver_print_request: TLV Length: 0
    INFO Apr 09 08:50:04.834280 [access_server]: tlvserver_print_request: TLV Cl Res: 0
    INFO Apr 09 08:50:04.834283 [access_server]: tlvserver_print_request: ---------------------------------
    DEBUG Apr 09 08:50:04.834286 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
    DEBUG Apr 09 08:50:04.834290 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x5668e1ad res_handler=(nil) handler_data=(nil)
    DEBUG Apr 09 08:50:04.834295 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:50:04.834298 [access_server]: (append_subsysqueue): acquiring lock 0x578c1518
    DEBUG Apr 09 08:50:04.834302 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:50:04.834306 [access_server]: (append_subsysqueue): released lock 0x578c1518
    INFO Apr 09 08:50:04.834309 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:50:04.834313 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
    DEBUG Apr 09 08:50:04.834316 [access_server]: (write_subsysqueue): acquiring lock 0x578c1518
    DEBUG Apr 09 08:50:04.834324 [access_server]: (write_subsysqueue): released lock 0x578c1518
    INFO Apr 09 08:50:04.834327 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=24 wq=0x578bf5d0 buf=0x578bf5d8 offset=0
    DEBUG Apr 09 08:50:04.834332 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:50:04.834338 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 25
    DEBUG Apr 09 08:50:04.834342 [EDIR_SYNC]: handle_server_events: EVENT_READ
    INFO Apr 09 08:50:04.834346 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:50:04.834351 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=25
    DEBUG Apr 09 08:50:04.834354 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x578bf378 req_handler=0x5668e1ad type=0 handler_data=(nil) res_handler=(nil)
    INFO Apr 09 08:50:04.834359 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:50:04.834363 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
    INFO Apr 09 08:50:04.834383 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
    DEBUG Apr 09 08:50:05.383021 [CAA]: (CA_epoll_wait): returning 0
    MESSAGE Apr 09 08:50:05.383062 [CAA]: (CA_keep_alive): access_server heartbeat
    DEBUG Apr 09 08:50:05.383066 [CAA]: (CA_keep_alive): Checking connections status
    MESSAGE Apr 09 08:50:05.383070 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
    DEBUG Apr 09 08:50:05.383074 [CAA]: (process_caa_messages): Waiting for CAA events
    DEBUG Apr 09 08:50:05.383077 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
    DEBUG Apr 09 08:50:50.426454 [CAA]: (CA_epoll_wait): returning 0
    MESSAGE Apr 09 08:50:50.426495 [CAA]: (CA_keep_alive): access_server heartbeat
    DEBUG Apr 09 08:50:50.426499 [CAA]: (CA_keep_alive): Checking connections status
    MESSAGE Apr 09 08:50:50.426503 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
    DEBUG Apr 09 08:50:50.426506 [CAA]: (process_caa_messages): Waiting for CAA events
    DEBUG Apr 09 08:50:50.426510 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
    DEBUG Apr 09 08:51:04.049448 [access_server]: tlvserver_handle_request: tlv request received
    INFO Apr 09 08:51:04.049464 [access_server]: tlvserver_print_request: ---------------------------------
    INFO Apr 09 08:51:04.049468 [access_server]: tlvserver_print_request: TLV ID: 140
    INFO Apr 09 08:51:04.049471 [access_server]: tlvserver_print_request: TLV Type: 0
    INFO Apr 09 08:51:04.049474 [access_server]: tlvserver_print_request: TLV Length: 0
    INFO Apr 09 08:51:04.049478 [access_server]: tlvserver_print_request: TLV Cl Res: 0
    INFO Apr 09 08:51:04.049481 [access_server]: tlvserver_print_request: ---------------------------------
    MESSAGE Apr 09 08:51:04.049484 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
    DEBUG Apr 09 08:51:04.049488 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:51:04.049745 [access_server]: tlvserver_handle_request: tlv request received
    INFO Apr 09 08:51:04.049752 [access_server]: tlvserver_print_request: ---------------------------------
    INFO Apr 09 08:51:04.049755 [access_server]: tlvserver_print_request: TLV ID: 112
    INFO Apr 09 08:51:04.049758 [access_server]: tlvserver_print_request: TLV Type: 0
    INFO Apr 09 08:51:04.049762 [access_server]: tlvserver_print_request: TLV Length: 0
    INFO Apr 09 08:51:04.049765 [access_server]: tlvserver_print_request: TLV Cl Res: 0
    INFO Apr 09 08:51:04.049768 [access_server]: tlvserver_print_request: ---------------------------------
    DEBUG Apr 09 08:51:04.049771 [access_server]: tlvserver_process_request: GOT TIMER ALERT.DO_ACCOUNTING
    DEBUG Apr 09 08:51:04.049778 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.049786 [access_server]: (bind_parameters_to_statement): Binding 2 parameters 0xff95f058 for query 0x5676fa18
    DEBUG Apr 09 08:51:04.049790 [access_server]: (bind_parameters_to_statement): Query name GET_SSO_LIVEUSERS
    DEBUG Apr 09 08:51:04.049796 [access_server]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 1613191089) succeeded
    DEBUG Apr 09 08:51:04.049800 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 34) succeeded
    INFO Apr 09 08:51:04.049815 [access_server]: (_sqlite_db_handle_get_logout_users): GET_SSO_LIVEUSERS found no entries (sqrs 101)
    DEBUG Apr 09 08:51:04.049819 [access_server]: (_sqlite_db_handle_get_logout_users): returning 0
    DEBUG Apr 09 08:51:04.049823 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.049826 [access_server]: (update_chromebook_sso_liveusers): No Chrome liveusers were found
    DEBUG Apr 09 08:51:04.049830 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.049834 [access_server]: (bind_parameters_to_statement): Binding 3 parameters 0xff95f068 for query 0x5676fcd4
    DEBUG Apr 09 08:51:04.049853 [access_server]: (bind_parameters_to_statement): Query name GET_DISCONNECTED_USERS
    DEBUG Apr 09 08:51:04.049858 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 1) succeeded
    DEBUG Apr 09 08:51:04.049861 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 2) succeeded
    DEBUG Apr 09 08:51:04.049865 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 4) succeeded
    INFO Apr 09 08:51:04.049871 [access_server]: (_sqlite_db_get_disconnected_users): GET_DISCONNECTED_USERS found no entries (sqrs 101)
    DEBUG Apr 09 08:51:04.049875 [access_server]: (_sqlite_db_get_disconnected_users): returning 0
    DEBUG Apr 09 08:51:04.049878 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.049882 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xff95e9c0 for query 0x5676fe28
    DEBUG Apr 09 08:51:04.049886 [access_server]: (bind_parameters_to_statement): Query name UPDATE_CLIENTLESS_USERS_USEDMIN
    DEBUG Apr 09 08:51:04.049889 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_CLIENTLESS_USERS_USEDMIN, 5) succeeded
    DEBUG Apr 09 08:51:04.049894 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.049913 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.049928 [access_server]: Executing command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile'
    DEBUG Apr 09 08:51:04.056593 [access_server]: dump_data_in_file: IPSET Command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile', Return Status:0
    DEBUG Apr 09 08:51:04.056620 [access_server]: (logout_timeout_users): invoked
    DEBUG Apr 09 08:51:04.056625 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=17 req_handler=0x566794c8 res_handler=0x56653210 handler_data=(nil)
    DEBUG Apr 09 08:51:04.056630 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:51:04.056633 [access_server]: (append_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056638 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:51:04.056642 [access_server]: (append_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056645 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.056649 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=17
    DEBUG Apr 09 08:51:04.056652 [access_server]: (write_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056659 [access_server]: (write_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056662 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x57893580 buf=0x57893588 offset=0
    DEBUG Apr 09 08:51:04.056666 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=18 req_handler=0x566794c8 res_handler=0x56653210 handler_data=(nil)
    DEBUG Apr 09 08:51:04.056670 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:51:04.056673 [access_server]: (append_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056677 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:51:04.056680 [access_server]: (append_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056683 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.056686 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=18
    DEBUG Apr 09 08:51:04.056690 [access_server]: (write_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056694 [access_server]: (write_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056697 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x57893580 buf=0x57893588 offset=0
    DEBUG Apr 09 08:51:04.056715 [access_server]: (subsys_submit_request): subsys_name=GENERIC req_type=1 req_handler=0x5668e769 res_handler=0x56653210 handler_data=(nil)
    DEBUG Apr 09 08:51:04.056718 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:51:04.056722 [access_server]: (append_subsysqueue): acquiring lock 0x57819be8
    DEBUG Apr 09 08:51:04.056726 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:51:04.056729 [access_server]: (append_subsysqueue): released lock 0x57819be8
    INFO Apr 09 08:51:04.056732 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.056736 [access_server]: (subsys_submit_request): GENERIC: request submitted, req_type=1
    DEBUG Apr 09 08:51:04.056739 [access_server]: (write_subsysqueue): acquiring lock 0x57819be8
    DEBUG Apr 09 08:51:04.056744 [access_server]: (write_subsysqueue): released lock 0x57819be8
    INFO Apr 09 08:51:04.056747 [access_server]: (write_subsysqueue): GENERIC CLIENT: written 16 bytes, fd=4 wq=0x57819e70 buf=0x57819e78 offset=0
    DEBUG Apr 09 08:51:04.056753 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=56 req_handler=0x566794c8 res_handler=0x56654124 handler_data=(nil)
    DEBUG Apr 09 08:51:04.056756 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:51:04.056759 [access_server]: (append_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056763 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:51:04.056766 [access_server]: (append_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056769 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.056773 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=56
    DEBUG Apr 09 08:51:04.056776 [access_server]: (write_subsysqueue): acquiring lock 0x57893308
    DEBUG Apr 09 08:51:04.056780 [access_server]: (write_subsysqueue): released lock 0x57893308
    INFO Apr 09 08:51:04.056783 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x57893580 buf=0x57893588 offset=0
    DEBUG Apr 09 08:51:04.056787 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:51:04.056802 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: event received on fd: 11
    DEBUG Apr 09 08:51:04.056806 [SQLITE_DB]: handle_server_events: EVENT_READ
    INFO Apr 09 08:51:04.056810 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
    INFO Apr 09 08:51:04.056816 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read 48 bytes, fd=11
    DEBUG Apr 09 08:51:04.056819 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x57893378 req_handler=0x566794c8 type=17 handler_data=(nil) res_handler=0x56653210
    DEBUG Apr 09 08:51:04.056825 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.056829 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf71fd4e4 for query 0x5676fdec
    DEBUG Apr 09 08:51:04.056833 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
    DEBUG Apr 09 08:51:04.056841 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 1024) succeeded
    DEBUG Apr 09 08:51:04.056845 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 16) succeeded
    DEBUG Apr 09 08:51:04.056849 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.056869 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.056873 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf71fd4e4 for query 0x5676fdec
    DEBUG Apr 09 08:51:04.056877 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
    DEBUG Apr 09 08:51:04.056880 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 100) succeeded
    DEBUG Apr 09 08:51:04.056888 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 35) succeeded
    DEBUG Apr 09 08:51:04.056892 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.056897 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.056901 [SQLITE_DB]: (bind_parameters_to_statement): Binding 6 parameters 0xf71fd4c4 for query 0x5676fe14
    DEBUG Apr 09 08:51:04.056904 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER
    DEBUG Apr 09 08:51:04.056909 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 1024) succeeded
    DEBUG Apr 09 08:51:04.056912 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 24) succeeded
    DEBUG Apr 09 08:51:04.056915 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 20) succeeded
    DEBUG Apr 09 08:51:04.056919 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 22) succeeded
    DEBUG Apr 09 08:51:04.056922 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 27) succeeded
    DEBUG Apr 09 08:51:04.056925 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 26) succeeded
    DEBUG Apr 09 08:51:04.056929 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.056935 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.056942 [SQLITE_DB]: (bind_parameters_to_statement): Binding 15 parameters 0xf71fd5c8 for query 0x5676faa4
    DEBUG Apr 09 08:51:04.056946 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_TIMEOUT_INACTIVENTLM_LIVEUSERS
    DEBUG Apr 09 08:51:04.056950 [SQLITE_DB]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1613191089) succeeded
    DEBUG Apr 09 08:51:04.056954 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1) succeeded
    DEBUG Apr 09 08:51:04.056958 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 4) succeeded
    DEBUG Apr 09 08:51:04.056961 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
    DEBUG Apr 09 08:51:04.056965 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 18) succeeded
    DEBUG Apr 09 08:51:04.056968 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 19) succeeded
    DEBUG Apr 09 08:51:04.056971 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 4747373) succeeded
    DEBUG Apr 09 08:51:04.056975 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 540) succeeded
    DEBUG Apr 09 08:51:04.056978 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 16) succeeded
    DEBUG Apr 09 08:51:04.056981 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 35) succeeded
    DEBUG Apr 09 08:51:04.056985 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
    DEBUG Apr 09 08:51:04.056988 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 20) succeeded
    DEBUG Apr 09 08:51:04.056991 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 22) succeeded
    DEBUG Apr 09 08:51:04.056995 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 24) succeeded
    DEBUG Apr 09 08:51:04.056998 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
    INFO Apr 09 08:51:04.057011 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): GET_TIMEOUT_INACTIVENTLM_LIVEUSERS found no entries (sqrs 101)
    DEBUG Apr 09 08:51:04.057015 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): returning 0
    DEBUG Apr 09 08:51:04.057018 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.057021 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:51:04.057025 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057028 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:51:04.057032 [SQLITE_DB]: (append_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057035 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.057038 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
    DEBUG Apr 09 08:51:04.057042 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057047 [SQLITE_DB]: (write_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057050 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x57893420 buf=0x57893428 offset=0
    DEBUG Apr 09 08:51:04.057054 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x57893388 req_handler=0x566794c8 type=18 handler_data=(nil) res_handler=0x56653210
    DEBUG Apr 09 08:51:04.057058 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.057061 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.057065 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:51:04.057068 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057071 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:51:04.057074 [SQLITE_DB]: (append_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057084 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.057088 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
    DEBUG Apr 09 08:51:04.057091 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057095 [SQLITE_DB]: (write_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057099 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x57893420 buf=0x57893428 offset=0
    DEBUG Apr 09 08:51:04.057102 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x57893398 req_handler=0x566794c8 type=56 handler_data=(nil) res_handler=0x56654124
    DEBUG Apr 09 08:51:04.057106 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.057109 [SQLITE_DB]: (bind_parameters_to_statement): Binding 4 parameters 0xf71fd5c8 for query 0x5676fb80
    DEBUG Apr 09 08:51:04.057113 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_IOS_ABT_TO_LOGOUT_USER
    DEBUG Apr 09 08:51:04.057117 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 1) succeeded
    DEBUG Apr 09 08:51:04.057121 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 19) succeeded
    DEBUG Apr 09 08:51:04.057124 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 128) succeeded
    DEBUG Apr 09 08:51:04.057127 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 0) succeeded
    INFO Apr 09 08:51:04.057134 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): GET_IOS_ABT_TO_LOGOUT_USER found no entries (sqrs 101)
    INFO Apr 09 08:51:04.057138 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): row count: 0
    DEBUG Apr 09 08:51:04.057141 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): returning 0
    DEBUG Apr 09 08:51:04.057145 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.057151 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Apr 09 08:51:04.057155 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057158 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Apr 09 08:51:04.057161 [SQLITE_DB]: (append_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057165 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:04.057168 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
    DEBUG Apr 09 08:51:04.057172 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x5789332c
    DEBUG Apr 09 08:51:04.057176 [SQLITE_DB]: (write_subsysqueue): released lock 0x5789332c
    INFO Apr 09 08:51:04.057179 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x57893420 buf=0x57893428 offset=0
    INFO Apr 09 08:51:04.057183 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
    INFO Apr 09 08:51:04.057187 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read blocked
    INFO Apr 09 08:51:04.057190 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: waiting for events...
    DEBUG Apr 09 08:51:04.057211 [GENERIC]: subsys_thread_main: GENERIC: event received on fd: 5
    DEBUG Apr 09 08:51:04.057215 [GENERIC]: handle_server_events: EVENT_READ
    INFO Apr 09 08:51:04.057218 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
    INFO Apr 09 08:51:04.057223 [GENERIC]: (do_handle_read): GENERIC server: read 16 bytes, fd=5
    DEBUG Apr 09 08:51:04.057226 [GENERIC]: (do_handle_read): GENERIC server tlv=0x57819c68 req_handler=0x5668e769 type=1 handler_data=(nil) res_handler=0x56653210
    DEBUG Apr 09 08:51:04.057230 [GENERIC]: generic_handle_request: DO PERIODIC AUTHORIZATION
    DEBUG Apr 09 08:51:04.057234 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Starts
    DEBUG Apr 09 08:51:04.057237 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
    DEBUG Apr 09 08:51:04.057242 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Apr 09 08:51:04.057245 [GENERIC]: (bind_parameters_to_statement): Binding 5 parameters 0xf75a68b8 for query 0x5676fbbc
    DEBUG Apr 09 08:51:04.057249 [GENERIC]: (bind_parameters_to_statement): Query name GET_BULK_LIVEUSERINFO_5
    DEBUG Apr 09 08:51:04.057254 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 4) succeeded
    DEBUG Apr 09 08:51:04.057257 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 5) succeeded
    DEBUG Apr 09 08:51:04.057260 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 2) succeeded
    DEBUG Apr 09 08:51:04.057264 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
    DEBUG Apr 09 08:51:04.057267 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 0) succeeded
    INFO Apr 09 08:51:04.057276 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 found no entries (sqrs 101)
    INFO Apr 09 08:51:04.057280 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): row count: 0
    DEBUG Apr 09 08:51:04.057284 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): returning 0
    DEBUG Apr 09 08:51:04.057287 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Apr 09 08:51:04.057291 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
    DEBUG Apr 09 08:51:04.057294 [GENERIC]: (auth_do_periodic_authorization): found=0
    DEBUG Apr 09 08:51:04.057297 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Over, logout_data=(nil)
    INFO Apr 09 08:51:04.057301 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
    INFO Apr 09 08:51:04.057305 [GENERIC]: (do_handle_read): GENERIC server: read blocked
    INFO Apr 09 08:51:04.057308 [GENERIC]: subsys_thread_main: GENERIC: waiting for events...
    DEBUG Apr 09 08:51:04.057317 [access_server]: handle_client_events: EVENT_READ
    INFO Apr 09 08:51:04.057321 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
    INFO Apr 09 08:51:04.057326 [access_server]: (do_handle_read): SQLITE_DB client: read 48 bytes, fd=10
    DEBUG Apr 09 08:51:04.057329 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x578934d8 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x56653210
    DEBUG Apr 09 08:51:04.057333 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
    DEBUG Apr 09 08:51:04.057336 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x578934e8 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x56653210
    DEBUG Apr 09 08:51:04.057340 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
    DEBUG Apr 09 08:51:04.057343 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x578934f8 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x56654124
    DEBUG Apr 09 08:51:04.057346 [access_server]: handle_ios_users_info: no user to send logout info
    INFO Apr 09 08:51:04.057350 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
    INFO Apr 09 08:51:04.057353 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
    DEBUG Apr 09 08:51:04.057357 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:51:05.047772 [access_server]: tlvserver_handle_request: tlv request received
    INFO Apr 09 08:51:05.047786 [access_server]: tlvserver_print_request: ---------------------------------
    INFO Apr 09 08:51:05.047790 [access_server]: tlvserver_print_request: TLV ID: 148
    INFO Apr 09 08:51:05.047793 [access_server]: tlvserver_print_request: TLV Type: 0
    INFO Apr 09 08:51:05.047797 [access_server]: tlvserver_print_request: TLV Length: 0
    INFO Apr 09 08:51:05.047800 [access_server]: tlvserver_print_request: TLV Cl Res: 0
    INFO Apr 09 08:51:05.047803 [access_server]: tlvserver_print_request: ---------------------------------
    DEBUG Apr 09 08:51:05.047806 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
    DEBUG Apr 09 08:51:05.047810 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x5668e1ad res_handler=(nil) handler_data=(nil)
    DEBUG Apr 09 08:51:05.047815 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Apr 09 08:51:05.047818 [access_server]: (append_subsysqueue): acquiring lock 0x578c1518
    DEBUG Apr 09 08:51:05.047823 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Apr 09 08:51:05.047827 [access_server]: (append_subsysqueue): released lock 0x578c1518
    INFO Apr 09 08:51:05.047830 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Apr 09 08:51:05.047834 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
    DEBUG Apr 09 08:51:05.047838 [access_server]: (write_subsysqueue): acquiring lock 0x578c1518
    DEBUG Apr 09 08:51:05.047845 [access_server]: (write_subsysqueue): released lock 0x578c1518
    INFO Apr 09 08:51:05.047848 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=24 wq=0x578bf5d0 buf=0x578bf5d8 offset=0
    DEBUG Apr 09 08:51:05.047852 [access_server]: (do_epoll): Waiting for events
    DEBUG Apr 09 08:51:05.047862 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 25
    DEBUG Apr 09 08:51:05.047865 [EDIR_SYNC]: handle_server_events: EVENT_READ
    INFO Apr 09 08:51:05.047869 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:51:05.047874 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=25
    DEBUG Apr 09 08:51:05.047877 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x578bf378 req_handler=0x5668e1ad type=0 handler_data=(nil) res_handler=(nil)
    INFO Apr 09 08:51:05.047882 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=25
    INFO Apr 09 08:51:05.047886 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
    INFO Apr 09 08:51:05.047902 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...

  • 0 2 days ago in reply to lokesh pardeshi

    Also, we have the following Sophos version - 


    SFOS 18.0.4 MR-4

Unfiltered HTML