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

Sophos connect cliente

Hello everyone

I have the problem in the sophos connect client when making an SSL configuration with OTP authentication, the client establishes the communication but does not authenticate, and is simply in the state of waiting to establish the connection, if I make an ipsec (remote access) connection with the same user, this procedure works.

Someone can help in the sense of being able to simply use the sophos connect client to establish the two types of VPN (IPSec remote access and SSL VPN remote access)

Below is the contents of the .pro file I use to make the SSL connection

[

{

"display_name": "VPN-SSL",

"gateway": "vpn.mydomain.pt",

"user_portal_port": 4434,

"otp": true, "2fa": 1,

"auto_connect_host": "",

"can_save_credentials": true,

"check_remote_availability": false,

"run_logon_script": false

}

]

Thank you

This thread was automatically locked due to age.

Top Replies

LuCar Toni over 4 years ago in reply to Antonio Rouqueiro +1

First of all: SSLVPN requires Login to User Portal and SSLVPN. So you need to check OTP for both facilities.

Parents

0 Antonio Rouqueiro over 4 years ago

Hi Harsh Patel

Fullscreen log_access_server.log Download

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2021.02.05 22:45:09 =~=~=~=~=~=~=~=~=~=~=~=
login as: admin
Authenticating with public key "Tecnirede"
Passphrase for key "Tecnirede": 
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Main Menu 

    1.  Network  Configuration
    2.  System   Configuration
    3.  Route    Configuration 
    4.  Device Console 
    5.  Device Management
    6.  VPN Management
    7.  Shutdown/Reboot Device
    0.  Exit 

    Select Menu Number [0-7]: 5
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Device Management 

    1.  Reset to Factory Defaults
    2.  Show Firmware(s)
    3.  Advanced Shell
    4.  Flush Device Reports
    0.  Exit

    Select Menu Number [0-4]: 3
[H[J

Sophos Firewall
===============
(C) Copyright 2000-2020 Sophos Limited and others. All rights reserved.
Sophos is a registered trademark of Sophos Limited and Sophos Group.
All other product and company names mentioned are trademarks or registered
trademarks of their respective owners.

For End User License Agreement - http://www.sophos.com/en-us/legal/sophos-end-user-license-agreement.aspx

NOTE: If not explicitly approved by Sophos support, any modifications
      done through this option will void your support.


SFV2C4_VM01_SFOS 18.0.4 MR-4# service access_server:debug -d -s nosync
200 OK
SFV2C4_VM01_SFOS 18.0.4 MR-4# service -S | grep access_server
access_server        RUNNING,DEBUG
SFV2C4_VM01_SFOS 18.0.4 MR-4# tail -f /log/acc
SFV2C4_VM01_SFOS 18.0.4 MR-4# tail -f /log/access_server.log[J
INFO      Feb 05 22:47:04.153889 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:47:04.153906 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:47:04.153964 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:47:04.153981 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:47:04.154000 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:47:04.154026 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:47:04.154041 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:47:04.154078 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:47:04.154102 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:47:04.154118 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
DEBUG     Feb 05 22:47:42.966843 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:47:42.966946 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:47:42.966980 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:47:42.967008 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:47:42.967023 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:47:42.967050 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
DEBUG     Feb 05 22:48:03.909867 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:03.909925 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:03.909941 [access_server]: tlvserver_print_request: TLV ID:	140
INFO      Feb 05 22:48:03.909955 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:03.909969 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:03.909983 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:03.909998 [access_server]: tlvserver_print_request: ---------------------------------
MESSAGE   Feb 05 22:48:03.910013 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
DEBUG     Feb 05 22:48:03.910037 [access_server]: check_timeout_cta_collector: now:11343 last_live:0
MESSAGE   Feb 05 22:48:03.910055 [access_server]: check_timeout_cta_collector: found timeout collector
DEBUG     Feb 05 22:48:03.910142 [access_server]: (do_sendto): send response of 9 bytes to IP: 192.168.199.77 PORT: 6677
DEBUG     Feb 05 22:48:03.910360 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.010432 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:04.010477 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:04.010492 [access_server]: tlvserver_print_request: TLV ID:	112
INFO      Feb 05 22:48:04.010519 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:04.010533 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:04.010547 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:04.010561 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:48:04.010575 [access_server]: tlvserver_process_request: GOT TIMER ALERT.DO_ACCOUNTING
DEBUG     Feb 05 22:48:04.010632 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.010740 [access_server]: (bind_parameters_to_statement): Binding 2 parameters 0xffac3b68 for query 0x566dba18
DEBUG     Feb 05 22:48:04.010772 [access_server]: (bind_parameters_to_statement): Query name GET_SSO_LIVEUSERS
DEBUG     Feb 05 22:48:04.010870 [access_server]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 1612553939) succeeded
DEBUG     Feb 05 22:48:04.010886 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 34) succeeded
INFO      Feb 05 22:48:04.011134 [access_server]: (_sqlite_db_handle_get_logout_users): GET_SSO_LIVEUSERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.011153 [access_server]: (_sqlite_db_handle_get_logout_users): returning 0
DEBUG     Feb 05 22:48:04.011175 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011190 [access_server]: (update_chromebook_sso_liveusers): No Chrome liveusers were found
DEBUG     Feb 05 22:48:04.011218 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.011233 [access_server]: (bind_parameters_to_statement): Binding 3 parameters 0xffac3b78 for query 0x566dbcd4
DEBUG     Feb 05 22:48:04.011248 [access_server]: (bind_parameters_to_statement): Query name GET_DISCONNECTED_USERS
DEBUG     Feb 05 22:48:04.011283 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 1) succeeded
DEBUG     Feb 05 22:48:04.011299 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 2) succeeded
DEBUG     Feb 05 22:48:04.011313 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 4) succeeded
INFO      Feb 05 22:48:04.011611 [access_server]: (_sqlite_db_get_disconnected_users): GET_DISCONNECTED_USERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.011627 [access_server]: (_sqlite_db_get_disconnected_users): returning 0
DEBUG     Feb 05 22:48:04.011642 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011680 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffac34d0 for query 0x566dbe28
DEBUG     Feb 05 22:48:04.011695 [access_server]: (bind_parameters_to_statement): Query name UPDATE_CLIENTLESS_USERS_USEDMIN
DEBUG     Feb 05 22:48:04.011717 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_CLIENTLESS_USERS_USEDMIN, 5) succeeded
DEBUG     Feb 05 22:48:04.011733 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.011786 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011855 [access_server]: Executing command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile'
DEBUG     Feb 05 22:48:04.072064 [access_server]: dump_data_in_file: IPSET Command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile', Return Status:0
DEBUG     Feb 05 22:48:04.072200 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072218 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072276 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072293 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072308 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072323 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 1) succeeded
DEBUG     Feb 05 22:48:04.072362 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.072710 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.072728 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072782 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072797 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072812 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072827 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072841 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 2) succeeded
DEBUG     Feb 05 22:48:04.072855 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.072888 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.072904 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072919 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072933 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072948 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072962 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072977 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 3) succeeded
DEBUG     Feb 05 22:48:04.072991 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.073023 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.073039 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.073053 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.073068 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 153991) succeeded
DEBUG     Feb 05 22:48:04.073082 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 1890644) succeeded
DEBUG     Feb 05 22:48:04.073097 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 2044635) succeeded
DEBUG     Feb 05 22:48:04.073112 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 5) succeeded
DEBUG     Feb 05 22:48:04.073126 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.073267 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.073295 [access_server]: (logout_timeout_users): invoked
DEBUG     Feb 05 22:48:04.073318 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=17 req_handler=0x565e54c8 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073348 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073363 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073388 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073414 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073429 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073443 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=17
DEBUG     Feb 05 22:48:04.073458 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073492 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073524 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.073565 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=18 req_handler=0x565e54c8 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073581 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073597 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073613 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073629 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073644 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073658 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=18
DEBUG     Feb 05 22:48:04.073674 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073695 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073709 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.073734 [access_server]: (subsys_submit_request): subsys_name=GENERIC req_type=1 req_handler=0x565fa769 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073751 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073766 [access_server]: (append_subsysqueue): acquiring lock 0x56de2c08
DEBUG     Feb 05 22:48:04.073793 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073808 [access_server]: (append_subsysqueue): released lock 0x56de2c08
INFO      Feb 05 22:48:04.073822 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073836 [access_server]: (subsys_submit_request): GENERIC: request submitted, req_type=1
DEBUG     Feb 05 22:48:04.073917 [access_server]: (write_subsysqueue): acquiring lock 0x56de2c08
DEBUG     Feb 05 22:48:04.073947 [access_server]: (write_subsysqueue): released lock 0x56de2c08
INFO      Feb 05 22:48:04.073961 [access_server]: (write_subsysqueue): GENERIC CLIENT: written 16 bytes, fd=4 wq=0x56de2e90 buf=0x56de2e98 offset=0
DEBUG     Feb 05 22:48:04.073991 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=56 req_handler=0x565e54c8 res_handler=0x565c0124 handler_data=(nil)
DEBUG     Feb 05 22:48:04.074006 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073961 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: event received on fd: 11
DEBUG     Feb 05 22:48:04.074020 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.074051 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.074052 [SQLITE_DB]: handle_server_events: EVENT_READ
DEBUG     Feb 05 22:48:04.074075 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.074079 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.074095 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.074109 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=56
INFO      Feb 05 22:48:04.074113 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read 32 bytes, fd=11
DEBUG     Feb 05 22:48:04.074124 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.074129 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd38 req_handler=0x565e54c8 type=17 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.074147 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.074161 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.074182 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074190 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.074273 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf6ffe4e4 for query 0x566dbdec
DEBUG     Feb 05 22:48:04.074293 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
DEBUG     Feb 05 22:48:04.074313 [GENERIC]: subsys_thread_main: GENERIC: event received on fd: 5
DEBUG     Feb 05 22:48:04.074330 [GENERIC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:48:04.074348 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
INFO      Feb 05 22:48:04.074371 [GENERIC]: (do_handle_read): GENERIC server: read 16 bytes, fd=5
DEBUG     Feb 05 22:48:04.074385 [GENERIC]: (do_handle_read): GENERIC server tlv=0x56de2c88 req_handler=0x565fa769 type=1 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.074400 [GENERIC]: generic_handle_request: DO PERIODIC AUTHORIZATION
DEBUG     Feb 05 22:48:04.074424 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 1024) succeeded
DEBUG     Feb 05 22:48:04.074433 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Starts
DEBUG     Feb 05 22:48:04.074442 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 16) succeeded
DEBUG     Feb 05 22:48:04.074449 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
DEBUG     Feb 05 22:48:04.074458 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074703 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.074718 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf6ffe4e4 for query 0x566dbdec
DEBUG     Feb 05 22:48:04.074733 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
DEBUG     Feb 05 22:48:04.074747 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 100) succeeded
DEBUG     Feb 05 22:48:04.074761 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 35) succeeded
DEBUG     Feb 05 22:48:04.074776 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074797 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.074813 [SQLITE_DB]: (bind_parameters_to_statement): Binding 6 parameters 0xf6ffe4c4 for query 0x566dbe14
DEBUG     Feb 05 22:48:04.074827 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER
DEBUG     Feb 05 22:48:04.074859 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 1024) succeeded
DEBUG     Feb 05 22:48:04.074875 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 24) succeeded
DEBUG     Feb 05 22:48:04.074890 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 20) succeeded
DEBUG     Feb 05 22:48:04.074904 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 22) succeeded
DEBUG     Feb 05 22:48:04.074919 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 27) succeeded
DEBUG     Feb 05 22:48:04.074934 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 26) succeeded
DEBUG     Feb 05 22:48:04.074948 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.075125 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075158 [SQLITE_DB]: (bind_parameters_to_statement): Binding 15 parameters 0xf6ffe5c8 for query 0x566dbaa4
DEBUG     Feb 05 22:48:04.075173 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_TIMEOUT_INACTIVENTLM_LIVEUSERS
DEBUG     Feb 05 22:48:04.075238 [SQLITE_DB]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1612553939) succeeded
DEBUG     Feb 05 22:48:04.075254 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1) succeeded
DEBUG     Feb 05 22:48:04.075268 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 4) succeeded
DEBUG     Feb 05 22:48:04.075283 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
DEBUG     Feb 05 22:48:04.075297 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 18) succeeded
DEBUG     Feb 05 22:48:04.075312 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 19) succeeded
DEBUG     Feb 05 22:48:04.075327 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 11343) succeeded
DEBUG     Feb 05 22:48:04.075341 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 540) succeeded
DEBUG     Feb 05 22:48:04.075356 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 16) succeeded
DEBUG     Feb 05 22:48:04.075370 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 35) succeeded
DEBUG     Feb 05 22:48:04.075385 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
DEBUG     Feb 05 22:48:04.075400 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 20) succeeded
DEBUG     Feb 05 22:48:04.075414 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 22) succeeded
DEBUG     Feb 05 22:48:04.075429 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 24) succeeded
DEBUG     Feb 05 22:48:04.075443 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
INFO      Feb 05 22:48:04.075599 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): GET_TIMEOUT_INACTIVENTLM_LIVEUSERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.075619 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): returning 0
DEBUG     Feb 05 22:48:04.075634 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075648 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
DEBUG     Feb 05 22:48:04.075662 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075676 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.075690 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075704 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.075718 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.075733 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075759 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075774 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
DEBUG     Feb 05 22:48:04.075779 [access_server]: handle_client_events: EVENT_READ
DEBUG     Feb 05 22:48:04.075797 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd48 req_handler=0x565e54c8 type=18 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.075815 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
INFO      Feb 05 22:48:04.075830 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
DEBUG     Feb 05 22:48:04.075831 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075849 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
INFO      Feb 05 22:48:04.075853 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.075876 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075879 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.075891 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.075895 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
DEBUG     Feb 05 22:48:04.075906 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075914 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.075921 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.075936 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.075949 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075951 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.075967 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.075970 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075985 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
DEBUG     Feb 05 22:48:04.075987 [access_server]: handle_client_events: EVENT_READ
INFO      Feb 05 22:48:04.076000 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.076003 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076021 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read 16 bytes, fd=11
INFO      Feb 05 22:48:04.076033 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.076036 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd38 req_handler=0x565e54c8 type=56 handler_data=(nil) res_handler=0x565c0124
DEBUG     Feb 05 22:48:04.076049 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.076052 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.076064 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
DEBUG     Feb 05 22:48:04.076068 [SQLITE_DB]: (bind_parameters_to_statement): Binding 4 parameters 0xf6ffe5c8 for query 0x566dbb80
INFO      Feb 05 22:48:04.076079 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
DEBUG     Feb 05 22:48:04.076084 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_IOS_ABT_TO_LOGOUT_USER
INFO      Feb 05 22:48:04.076098 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.076115 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.076120 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 1) succeeded
DEBUG     Feb 05 22:48:04.076136 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 19) succeeded
DEBUG     Feb 05 22:48:04.076150 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 128) succeeded
DEBUG     Feb 05 22:48:04.076165 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 0) succeeded
INFO      Feb 05 22:48:04.076207 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): GET_IOS_ABT_TO_LOGOUT_USER found no entries (sqrs 101)
INFO      Feb 05 22:48:04.076223 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): row count: 0
DEBUG     Feb 05 22:48:04.076240 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): returning 0
DEBUG     Feb 05 22:48:04.076255 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.076282 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
DEBUG     Feb 05 22:48:04.076296 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076310 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.076324 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.076338 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.076351 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.076365 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076388 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076397 [access_server]: handle_client_events: EVENT_READ
INFO      Feb 05 22:48:04.076403 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
INFO      Feb 05 22:48:04.076413 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076426 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.076438 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.076453 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565c0124
INFO      Feb 05 22:48:04.076464 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read blocked
DEBUG     Feb 05 22:48:04.076468 [access_server]: handle_ios_users_info: no user to send logout info
INFO      Feb 05 22:48:04.076480 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: waiting for events...
INFO      Feb 05 22:48:04.076483 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076503 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.076517 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.076551 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.076569 [GENERIC]: (bind_parameters_to_statement): Binding 5 parameters 0xf75928b8 for query 0x566dbbbc
DEBUG     Feb 05 22:48:04.076584 [GENERIC]: (bind_parameters_to_statement): Query name GET_BULK_LIVEUSERINFO_5
DEBUG     Feb 05 22:48:04.076621 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 4) succeeded
DEBUG     Feb 05 22:48:04.076636 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 5) succeeded
DEBUG     Feb 05 22:48:04.076651 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 2) succeeded
DEBUG     Feb 05 22:48:04.076665 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
DEBUG     Feb 05 22:48:04.076680 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 0) succeeded
DEBUG     Feb 05 22:48:04.076877 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=1 userid=26 attr.starttime=272 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=576244 cycleused_minutes=576244 renewdate='2018-11-19'                upload=21236874038 download=1677698051 cycleupload=21236874038 cycledownload=1677698051
DEBUG     Feb 05 22:48:04.076905 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=2 userid=25 attr.starttime=274 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=386722 cycleused_minutes=386722 renewdate='2018-11-19'                upload=69756631751 download=85404283856 cycleupload=69756631751 cycledownload=85404283856
DEBUG     Feb 05 22:48:04.076927 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=3 userid=9 attr.starttime=292 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=729195 cycleused_minutes=729195 renewdate='2018-10-18'                upload=15735863793 download=32772236487 cycleupload=15735863793 cycledownload=32772236487
DEBUG     Feb 05 22:48:04.076963 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=5 userid=25 attr.starttime=392 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=386722 cycleused_minutes=386722 renewdate='2018-11-19'                upload=69756631751 download=85404283856 cycleupload=69756631751 cycledownload=85404283856
DEBUG     Feb 05 22:48:04.076993 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): SQLITE_DONE
INFO      Feb 05 22:48:04.077008 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): row count: 4
DEBUG     Feb 05 22:48:04.077024 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): returning 0
DEBUG     Feb 05 22:48:04.077038 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077057 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 4
DEBUG     Feb 05 22:48:04.077079 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:576244, cycleused_min:576244, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.077122 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.077137 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 576247
DEBUG     Feb 05 22:48:04.077151 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077170 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.077185 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.077228 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.077243 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 1) succeeded
DEBUG     Feb 05 22:48:04.077323 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077343 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=272
DEBUG     Feb 05 22:48:04.077387 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.077408 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.077423 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.077437 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=576247}
DEBUG     Feb 05 22:48:04.077458 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:576247
DEBUG     Feb 05 22:48:04.077473 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.077486 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.077501 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.077515 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.077560 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.077576 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 576247) succeeded
DEBUG     Feb 05 22:48:04.077591 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 576247) succeeded
DEBUG     Feb 05 22:48:04.077605 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 21236874038) succeeded
DEBUG     Feb 05 22:48:04.077651 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1677698051) succeeded
DEBUG     Feb 05 22:48:04.077667 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 26) succeeded
DEBUG     Feb 05 22:48:04.077681 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077718 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077734 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:386722, cycleused_min:386722, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.077749 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.077764 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 386725
DEBUG     Feb 05 22:48:04.077778 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077793 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.077807 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.077821 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.077835 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 2) succeeded
DEBUG     Feb 05 22:48:04.077880 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077895 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=274
DEBUG     Feb 05 22:48:04.077910 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.077924 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.077938 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.077952 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=386725}
DEBUG     Feb 05 22:48:04.077966 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:386725
DEBUG     Feb 05 22:48:04.077980 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.077994 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078008 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078022 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078036 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078051 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078065 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078080 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 69756631751) succeeded
DEBUG     Feb 05 22:48:04.078095 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 85404283856) succeeded
DEBUG     Feb 05 22:48:04.078109 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 25) succeeded
DEBUG     Feb 05 22:48:04.078124 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078151 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078166 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:729195, cycleused_min:729195, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.078181 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.078196 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 729198
DEBUG     Feb 05 22:48:04.078231 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078247 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.078261 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.078275 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.078290 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 3) succeeded
DEBUG     Feb 05 22:48:04.078322 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078337 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=292
DEBUG     Feb 05 22:48:04.078351 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.078365 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.078380 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.078393 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=729198}
DEBUG     Feb 05 22:48:04.078408 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:729198
DEBUG     Feb 05 22:48:04.078422 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.078435 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078449 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078464 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078478 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078493 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 729198) succeeded
DEBUG     Feb 05 22:48:04.078507 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 729198) succeeded
DEBUG     Feb 05 22:48:04.078522 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 15735863793) succeeded
DEBUG     Feb 05 22:48:04.078537 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 32772236487) succeeded
DEBUG     Feb 05 22:48:04.078551 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 9) succeeded
DEBUG     Feb 05 22:48:04.078569 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078596 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078611 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:386722, cycleused_min:386722, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.078627 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.078642 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 386725
DEBUG     Feb 05 22:48:04.078656 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078671 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.078686 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.078700 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.078715 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 5) succeeded
DEBUG     Feb 05 22:48:04.078747 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078762 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=392
DEBUG     Feb 05 22:48:04.078789 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.078803 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.078817 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.078831 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=386725}
DEBUG     Feb 05 22:48:04.078845 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:386725
DEBUG     Feb 05 22:48:04.078859 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.078873 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078887 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078901 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078915 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078930 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078944 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078959 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 69756631751) succeeded
DEBUG     Feb 05 22:48:04.078974 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 85404283856) succeeded
DEBUG     Feb 05 22:48:04.078988 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 25) succeeded
DEBUG     Feb 05 22:48:04.079003 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.079024 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.079039 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.079054 [GENERIC]: (bind_parameters_to_statement): Binding 5 parameters 0xf75928b8 for query 0x566dbbbc
DEBUG     Feb 05 22:48:04.079069 [GENERIC]: (bind_parameters_to_statement): Query name GET_BULK_LIVEUSERINFO_5
DEBUG     Feb 05 22:48:04.079083 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 4) succeeded
DEBUG     Feb 05 22:48:04.079157 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 5) succeeded
DEBUG     Feb 05 22:48:04.079173 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 2) succeeded
DEBUG     Feb 05 22:48:04.079188 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
DEBUG     Feb 05 22:48:04.079202 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
INFO      Feb 05 22:48:04.079239 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 found no entries (sqrs 101)
INFO      Feb 05 22:48:04.079255 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): row count: 0
DEBUG     Feb 05 22:48:04.079269 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): returning 0
DEBUG     Feb 05 22:48:04.079283 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.079297 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
DEBUG     Feb 05 22:48:04.079311 [GENERIC]: (auth_do_periodic_authorization): found=0
DEBUG     Feb 05 22:48:04.079325 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Over, logout_data=(nil)
INFO      Feb 05 22:48:04.079340 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
INFO      Feb 05 22:48:04.079361 [GENERIC]: (do_handle_read): GENERIC server: read blocked
INFO      Feb 05 22:48:04.079375 [GENERIC]: subsys_thread_main: GENERIC: waiting for events...
DEBUG     Feb 05 22:48:04.678241 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:04.678348 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:04.678364 [access_server]: tlvserver_print_request: TLV ID:	148
INFO      Feb 05 22:48:04.678378 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:04.678392 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:04.678407 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:04.678420 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:48:04.678435 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
DEBUG     Feb 05 22:48:04.678456 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x565fa1ad res_handler=(nil) handler_data=(nil)
DEBUG     Feb 05 22:48:04.678479 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.678494 [access_server]: (append_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:48:04.678509 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.678524 [access_server]: (append_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:48:04.678538 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.678553 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
DEBUG     Feb 05 22:48:04.678569 [access_server]: (write_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:48:04.678597 [access_server]: (write_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:48:04.678612 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:48:04.678628 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.678741 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:48:04.678758 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:48:04.678774 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:48:04.678799 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:48:04.678813 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:48:04.678842 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:48:04.678862 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:48:04.678877 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
ERROR     Feb 05 22:48:28.011726 [CAA]: (CA_epoll_wait): time_to_keep_alive=-1000, after=1612565308, before=1612565262
MESSAGE   Feb 05 22:48:28.011792 [CAA]: (CA_epoll_wait): returning nfds 0
DEBUG     Feb 05 22:48:28.011807 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:48:28.011823 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:48:28.011859 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:48:28.011875 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:48:28.011889 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:48:28.011904 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
DEBUG     Feb 05 22:49:03.682639 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:49:03.682691 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:49:03.682706 [access_server]: tlvserver_print_request: TLV ID:	140
INFO      Feb 05 22:49:03.682720 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:49:03.682734 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:49:03.682748 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:49:03.682762 [access_server]: tlvserver_print_request: ---------------------------------
MESSAGE   Feb 05 22:49:03.682821 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
DEBUG     Feb 05 22:49:03.682841 [access_server]: check_timeout_cta_collector: now:11402 last_live:0
MESSAGE   Feb 05 22:49:03.682870 [access_server]: check_timeout_cta_collector: found timeout collector
DEBUG     Feb 05 22:49:03.682891 [access_server]: (do_sendto): send response of 9 bytes to IP: 192.168.199.77 PORT: 6677
DEBUG     Feb 05 22:49:03.683080 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:49:04.467518 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:49:04.467569 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:49:04.467584 [access_server]: tlvserver_print_request: TLV ID:	148
INFO      Feb 05 22:49:04.467598 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:49:04.467612 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:49:04.467626 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:49:04.467640 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:49:04.467654 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
DEBUG     Feb 05 22:49:04.467677 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x565fa1ad res_handler=(nil) handler_data=(nil)
DEBUG     Feb 05 22:49:04.467700 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:49:04.467714 [access_server]: (append_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:49:04.467729 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:49:04.467743 [access_server]: (append_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:49:04.467757 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:49:04.467772 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
DEBUG     Feb 05 22:49:04.467788 [access_server]: (write_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:49:04.467814 [access_server]: (write_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:49:04.467829 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:49:04.467845 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:49:04.467889 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:49:04.467906 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:49:04.467921 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:49:04.467945 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:49:04.467960 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:49:04.467982 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:49:04.468002 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:49:04.468017 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
DEBUG     Feb 05 22:49:13.056039 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:49:13.056088 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:49:13.056106 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:49:13.056122 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:49:13.056136 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:49:13.056151 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
^C
SFV2C4_VM01_SFOS 18.0.4 MR-4# exit
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Device Management 

    1.  Reset to Factory Defaults
    2.  Show Firmware(s)
    3.  Advanced Shell
    4.  Flush Device Reports
    0.  Exit

    Select Menu Number [0-4]: 0
Exit
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Main Menu 

    1.  Network  Configuration
    2.  System   Configuration
    3.  Route    Configuration 
    4.  Device Console 
    5.  Device Management
    6.  VPN Management
    7.  Shutdown/Reboot Device
    0.  Exit 

    Select Menu Number [0-7]: 0
Exiting Device Menu

After restarting the appliance, the authentication service was active, but I am still unable to connect as a user with otp active, all other methods work, this user is configured to authenticate with 2fa, I have the tb appliance configured, if it is via ipsec works perfectly, only ssl with otp and it doesn't work. attach the access_sever log thank you

Reply

0 Antonio Rouqueiro over 4 years ago

Hi Harsh Patel

Fullscreen log_access_server.log Download

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2021.02.05 22:45:09 =~=~=~=~=~=~=~=~=~=~=~=
login as: admin
Authenticating with public key "Tecnirede"
Passphrase for key "Tecnirede": 
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Main Menu 

    1.  Network  Configuration
    2.  System   Configuration
    3.  Route    Configuration 
    4.  Device Console 
    5.  Device Management
    6.  VPN Management
    7.  Shutdown/Reboot Device
    0.  Exit 

    Select Menu Number [0-7]: 5
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Device Management 

    1.  Reset to Factory Defaults
    2.  Show Firmware(s)
    3.  Advanced Shell
    4.  Flush Device Reports
    0.  Exit

    Select Menu Number [0-4]: 3
[H[J

Sophos Firewall
===============
(C) Copyright 2000-2020 Sophos Limited and others. All rights reserved.
Sophos is a registered trademark of Sophos Limited and Sophos Group.
All other product and company names mentioned are trademarks or registered
trademarks of their respective owners.

For End User License Agreement - http://www.sophos.com/en-us/legal/sophos-end-user-license-agreement.aspx

NOTE: If not explicitly approved by Sophos support, any modifications
      done through this option will void your support.


SFV2C4_VM01_SFOS 18.0.4 MR-4# service access_server:debug -d -s nosync
200 OK
SFV2C4_VM01_SFOS 18.0.4 MR-4# service -S | grep access_server
access_server        RUNNING,DEBUG
SFV2C4_VM01_SFOS 18.0.4 MR-4# tail -f /log/acc
SFV2C4_VM01_SFOS 18.0.4 MR-4# tail -f /log/access_server.log[J
INFO      Feb 05 22:47:04.153889 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:47:04.153906 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:47:04.153964 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:47:04.153981 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:47:04.154000 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:47:04.154026 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:47:04.154041 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:47:04.154078 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:47:04.154102 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:47:04.154118 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
DEBUG     Feb 05 22:47:42.966843 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:47:42.966946 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:47:42.966980 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:47:42.967008 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:47:42.967023 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:47:42.967050 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
DEBUG     Feb 05 22:48:03.909867 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:03.909925 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:03.909941 [access_server]: tlvserver_print_request: TLV ID:	140
INFO      Feb 05 22:48:03.909955 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:03.909969 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:03.909983 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:03.909998 [access_server]: tlvserver_print_request: ---------------------------------
MESSAGE   Feb 05 22:48:03.910013 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
DEBUG     Feb 05 22:48:03.910037 [access_server]: check_timeout_cta_collector: now:11343 last_live:0
MESSAGE   Feb 05 22:48:03.910055 [access_server]: check_timeout_cta_collector: found timeout collector
DEBUG     Feb 05 22:48:03.910142 [access_server]: (do_sendto): send response of 9 bytes to IP: 192.168.199.77 PORT: 6677
DEBUG     Feb 05 22:48:03.910360 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.010432 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:04.010477 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:04.010492 [access_server]: tlvserver_print_request: TLV ID:	112
INFO      Feb 05 22:48:04.010519 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:04.010533 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:04.010547 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:04.010561 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:48:04.010575 [access_server]: tlvserver_process_request: GOT TIMER ALERT.DO_ACCOUNTING
DEBUG     Feb 05 22:48:04.010632 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.010740 [access_server]: (bind_parameters_to_statement): Binding 2 parameters 0xffac3b68 for query 0x566dba18
DEBUG     Feb 05 22:48:04.010772 [access_server]: (bind_parameters_to_statement): Query name GET_SSO_LIVEUSERS
DEBUG     Feb 05 22:48:04.010870 [access_server]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 1612553939) succeeded
DEBUG     Feb 05 22:48:04.010886 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_SSO_LIVEUSERS, 34) succeeded
INFO      Feb 05 22:48:04.011134 [access_server]: (_sqlite_db_handle_get_logout_users): GET_SSO_LIVEUSERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.011153 [access_server]: (_sqlite_db_handle_get_logout_users): returning 0
DEBUG     Feb 05 22:48:04.011175 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011190 [access_server]: (update_chromebook_sso_liveusers): No Chrome liveusers were found
DEBUG     Feb 05 22:48:04.011218 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.011233 [access_server]: (bind_parameters_to_statement): Binding 3 parameters 0xffac3b78 for query 0x566dbcd4
DEBUG     Feb 05 22:48:04.011248 [access_server]: (bind_parameters_to_statement): Query name GET_DISCONNECTED_USERS
DEBUG     Feb 05 22:48:04.011283 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 1) succeeded
DEBUG     Feb 05 22:48:04.011299 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 2) succeeded
DEBUG     Feb 05 22:48:04.011313 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_DISCONNECTED_USERS, 4) succeeded
INFO      Feb 05 22:48:04.011611 [access_server]: (_sqlite_db_get_disconnected_users): GET_DISCONNECTED_USERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.011627 [access_server]: (_sqlite_db_get_disconnected_users): returning 0
DEBUG     Feb 05 22:48:04.011642 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011680 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffac34d0 for query 0x566dbe28
DEBUG     Feb 05 22:48:04.011695 [access_server]: (bind_parameters_to_statement): Query name UPDATE_CLIENTLESS_USERS_USEDMIN
DEBUG     Feb 05 22:48:04.011717 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_CLIENTLESS_USERS_USEDMIN, 5) succeeded
DEBUG     Feb 05 22:48:04.011733 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.011786 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.011855 [access_server]: Executing command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile'
DEBUG     Feb 05 22:48:04.072064 [access_server]: dump_data_in_file: IPSET Command '/sbin/ipsetelite -L users -c -m >> /tmp/authd_datafile', Return Status:0
DEBUG     Feb 05 22:48:04.072200 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072218 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072276 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072293 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072308 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072323 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 1) succeeded
DEBUG     Feb 05 22:48:04.072362 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.072710 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.072728 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072782 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072797 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072812 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072827 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072841 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 2) succeeded
DEBUG     Feb 05 22:48:04.072855 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.072888 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.072904 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.072919 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.072933 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072948 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072962 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 0) succeeded
DEBUG     Feb 05 22:48:04.072977 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 3) succeeded
DEBUG     Feb 05 22:48:04.072991 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.073023 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.073039 [access_server]: (bind_parameters_to_statement): Binding 4 parameters 0xffac348c for query 0x566dbdd8
DEBUG     Feb 05 22:48:04.073053 [access_server]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_DATATRANSFER
DEBUG     Feb 05 22:48:04.073068 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 153991) succeeded
DEBUG     Feb 05 22:48:04.073082 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 1890644) succeeded
DEBUG     Feb 05 22:48:04.073097 [access_server]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 2044635) succeeded
DEBUG     Feb 05 22:48:04.073112 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_DATATRANSFER, 5) succeeded
DEBUG     Feb 05 22:48:04.073126 [access_server]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.073267 [access_server]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.073295 [access_server]: (logout_timeout_users): invoked
DEBUG     Feb 05 22:48:04.073318 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=17 req_handler=0x565e54c8 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073348 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073363 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073388 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073414 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073429 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073443 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=17
DEBUG     Feb 05 22:48:04.073458 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073492 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073524 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.073565 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=18 req_handler=0x565e54c8 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073581 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073597 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073613 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073629 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073644 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073658 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=18
DEBUG     Feb 05 22:48:04.073674 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.073695 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.073709 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.073734 [access_server]: (subsys_submit_request): subsys_name=GENERIC req_type=1 req_handler=0x565fa769 res_handler=0x565bf210 handler_data=(nil)
DEBUG     Feb 05 22:48:04.073751 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073766 [access_server]: (append_subsysqueue): acquiring lock 0x56de2c08
DEBUG     Feb 05 22:48:04.073793 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.073808 [access_server]: (append_subsysqueue): released lock 0x56de2c08
INFO      Feb 05 22:48:04.073822 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.073836 [access_server]: (subsys_submit_request): GENERIC: request submitted, req_type=1
DEBUG     Feb 05 22:48:04.073917 [access_server]: (write_subsysqueue): acquiring lock 0x56de2c08
DEBUG     Feb 05 22:48:04.073947 [access_server]: (write_subsysqueue): released lock 0x56de2c08
INFO      Feb 05 22:48:04.073961 [access_server]: (write_subsysqueue): GENERIC CLIENT: written 16 bytes, fd=4 wq=0x56de2e90 buf=0x56de2e98 offset=0
DEBUG     Feb 05 22:48:04.073991 [access_server]: (subsys_submit_request): subsys_name=SQLITE_DB req_type=56 req_handler=0x565e54c8 res_handler=0x565c0124 handler_data=(nil)
DEBUG     Feb 05 22:48:04.074006 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.073961 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: event received on fd: 11
DEBUG     Feb 05 22:48:04.074020 [access_server]: (append_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.074051 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.074052 [SQLITE_DB]: handle_server_events: EVENT_READ
DEBUG     Feb 05 22:48:04.074075 [access_server]: (append_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.074079 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.074095 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.074109 [access_server]: (subsys_submit_request): SQLITE_DB: request submitted, req_type=56
INFO      Feb 05 22:48:04.074113 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read 32 bytes, fd=11
DEBUG     Feb 05 22:48:04.074124 [access_server]: (write_subsysqueue): acquiring lock 0x56e5bc48
DEBUG     Feb 05 22:48:04.074129 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd38 req_handler=0x565e54c8 type=17 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.074147 [access_server]: (write_subsysqueue): released lock 0x56e5bc48
INFO      Feb 05 22:48:04.074161 [access_server]: (write_subsysqueue): SQLITE_DB CLIENT: written 16 bytes, fd=10 wq=0x56e5cf40 buf=0x56e5cf48 offset=0
DEBUG     Feb 05 22:48:04.074182 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074190 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.074273 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf6ffe4e4 for query 0x566dbdec
DEBUG     Feb 05 22:48:04.074293 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
DEBUG     Feb 05 22:48:04.074313 [GENERIC]: subsys_thread_main: GENERIC: event received on fd: 5
DEBUG     Feb 05 22:48:04.074330 [GENERIC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:48:04.074348 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
INFO      Feb 05 22:48:04.074371 [GENERIC]: (do_handle_read): GENERIC server: read 16 bytes, fd=5
DEBUG     Feb 05 22:48:04.074385 [GENERIC]: (do_handle_read): GENERIC server tlv=0x56de2c88 req_handler=0x565fa769 type=1 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.074400 [GENERIC]: generic_handle_request: DO PERIODIC AUTHORIZATION
DEBUG     Feb 05 22:48:04.074424 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 1024) succeeded
DEBUG     Feb 05 22:48:04.074433 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Starts
DEBUG     Feb 05 22:48:04.074442 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 16) succeeded
DEBUG     Feb 05 22:48:04.074449 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
DEBUG     Feb 05 22:48:04.074458 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074703 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.074718 [SQLITE_DB]: (bind_parameters_to_statement): Binding 2 parameters 0xf6ffe4e4 for query 0x566dbdec
DEBUG     Feb 05 22:48:04.074733 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_INACTIVITY_TIMEOUT_COUNTER
DEBUG     Feb 05 22:48:04.074747 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 100) succeeded
DEBUG     Feb 05 22:48:04.074761 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_INACTIVITY_TIMEOUT_COUNTER, 35) succeeded
DEBUG     Feb 05 22:48:04.074776 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.074797 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.074813 [SQLITE_DB]: (bind_parameters_to_statement): Binding 6 parameters 0xf6ffe4c4 for query 0x566dbe14
DEBUG     Feb 05 22:48:04.074827 [SQLITE_DB]: (bind_parameters_to_statement): Query name UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER
DEBUG     Feb 05 22:48:04.074859 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 1024) succeeded
DEBUG     Feb 05 22:48:04.074875 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 24) succeeded
DEBUG     Feb 05 22:48:04.074890 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 20) succeeded
DEBUG     Feb 05 22:48:04.074904 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 22) succeeded
DEBUG     Feb 05 22:48:04.074919 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 27) succeeded
DEBUG     Feb 05 22:48:04.074934 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_MULTIPLE_INACTIVITY_TIMEOUT_6_COUNTER, 26) succeeded
DEBUG     Feb 05 22:48:04.074948 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.075125 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075158 [SQLITE_DB]: (bind_parameters_to_statement): Binding 15 parameters 0xf6ffe5c8 for query 0x566dbaa4
DEBUG     Feb 05 22:48:04.075173 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_TIMEOUT_INACTIVENTLM_LIVEUSERS
DEBUG     Feb 05 22:48:04.075238 [SQLITE_DB]: (check_sqlite_bind_long_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1612553939) succeeded
DEBUG     Feb 05 22:48:04.075254 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 1) succeeded
DEBUG     Feb 05 22:48:04.075268 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 4) succeeded
DEBUG     Feb 05 22:48:04.075283 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
DEBUG     Feb 05 22:48:04.075297 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 18) succeeded
DEBUG     Feb 05 22:48:04.075312 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 19) succeeded
DEBUG     Feb 05 22:48:04.075327 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 11343) succeeded
DEBUG     Feb 05 22:48:04.075341 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 540) succeeded
DEBUG     Feb 05 22:48:04.075356 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 16) succeeded
DEBUG     Feb 05 22:48:04.075370 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 35) succeeded
DEBUG     Feb 05 22:48:04.075385 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
DEBUG     Feb 05 22:48:04.075400 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 20) succeeded
DEBUG     Feb 05 22:48:04.075414 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 22) succeeded
DEBUG     Feb 05 22:48:04.075429 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 24) succeeded
DEBUG     Feb 05 22:48:04.075443 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_TIMEOUT_INACTIVENTLM_LIVEUSERS, 2) succeeded
INFO      Feb 05 22:48:04.075599 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): GET_TIMEOUT_INACTIVENTLM_LIVEUSERS found no entries (sqrs 101)
DEBUG     Feb 05 22:48:04.075619 [SQLITE_DB]: (_sqlite_db_handle_get_logout_users): returning 0
DEBUG     Feb 05 22:48:04.075634 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075648 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
DEBUG     Feb 05 22:48:04.075662 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075676 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.075690 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075704 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.075718 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.075733 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075759 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075774 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
DEBUG     Feb 05 22:48:04.075779 [access_server]: handle_client_events: EVENT_READ
DEBUG     Feb 05 22:48:04.075797 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd48 req_handler=0x565e54c8 type=18 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.075815 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
INFO      Feb 05 22:48:04.075830 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
DEBUG     Feb 05 22:48:04.075831 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.075849 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
INFO      Feb 05 22:48:04.075853 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.075876 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.075879 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.075891 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.075895 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
DEBUG     Feb 05 22:48:04.075906 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075914 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.075921 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.075936 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.075949 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075951 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.075967 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.075970 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.075985 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
DEBUG     Feb 05 22:48:04.075987 [access_server]: handle_client_events: EVENT_READ
INFO      Feb 05 22:48:04.076000 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.076003 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076021 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read 16 bytes, fd=11
INFO      Feb 05 22:48:04.076033 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.076036 [SQLITE_DB]: (do_handle_read): SQLITE_DB server tlv=0x56e5cd38 req_handler=0x565e54c8 type=56 handler_data=(nil) res_handler=0x565c0124
DEBUG     Feb 05 22:48:04.076049 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565bf210
DEBUG     Feb 05 22:48:04.076052 [SQLITE_DB]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.076064 [access_server]: handle_logout_users: handler_data NULL. No Users to Logout
DEBUG     Feb 05 22:48:04.076068 [SQLITE_DB]: (bind_parameters_to_statement): Binding 4 parameters 0xf6ffe5c8 for query 0x566dbb80
INFO      Feb 05 22:48:04.076079 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
DEBUG     Feb 05 22:48:04.076084 [SQLITE_DB]: (bind_parameters_to_statement): Query name GET_IOS_ABT_TO_LOGOUT_USER
INFO      Feb 05 22:48:04.076098 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.076115 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.076120 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 1) succeeded
DEBUG     Feb 05 22:48:04.076136 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 19) succeeded
DEBUG     Feb 05 22:48:04.076150 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 128) succeeded
DEBUG     Feb 05 22:48:04.076165 [SQLITE_DB]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_IOS_ABT_TO_LOGOUT_USER, 0) succeeded
INFO      Feb 05 22:48:04.076207 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): GET_IOS_ABT_TO_LOGOUT_USER found no entries (sqrs 101)
INFO      Feb 05 22:48:04.076223 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): row count: 0
DEBUG     Feb 05 22:48:04.076240 [SQLITE_DB]: (_sqlite_db_get_ios_user_info): returning 0
DEBUG     Feb 05 22:48:04.076255 [SQLITE_DB]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.076282 [SQLITE_DB]: (append_subsysqueue): : SERVER, datasize: 16
DEBUG     Feb 05 22:48:04.076296 [SQLITE_DB]: (append_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076310 [SQLITE_DB]: (append_subsysqueue): : SERVER, remlen: 160
DEBUG     Feb 05 22:48:04.076324 [SQLITE_DB]: (append_subsysqueue): released lock 0x56e5bc6c
INFO      Feb 05 22:48:04.076338 [SQLITE_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.076351 [SQLITE_DB]: subsys_submit_response: SQLITE_DB: response submitted, res_type=0
DEBUG     Feb 05 22:48:04.076365 [SQLITE_DB]: (write_subsysqueue): acquiring lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076388 [SQLITE_DB]: (write_subsysqueue): released lock 0x56e5bc6c
DEBUG     Feb 05 22:48:04.076397 [access_server]: handle_client_events: EVENT_READ
INFO      Feb 05 22:48:04.076403 [SQLITE_DB]: (write_subsysqueue): SQLITE_DB SERVER: written 16 bytes, fd=11 wq=0x56e5cde0 buf=0x56e5cde8 offset=0
INFO      Feb 05 22:48:04.076413 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076426 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: READING... fd=11
INFO      Feb 05 22:48:04.076438 [access_server]: (do_handle_read): SQLITE_DB client: read 16 bytes, fd=10
DEBUG     Feb 05 22:48:04.076453 [access_server]: (do_handle_read): SQLITE_DB client tlv=0x56e5ce98 req_handler=(nil) type=0 handler_data=(nil) res_handler=0x565c0124
INFO      Feb 05 22:48:04.076464 [SQLITE_DB]: (do_handle_read): SQLITE_DB server: read blocked
DEBUG     Feb 05 22:48:04.076468 [access_server]: handle_ios_users_info: no user to send logout info
INFO      Feb 05 22:48:04.076480 [SQLITE_DB]: subsys_thread_main: SQLITE_DB: waiting for events...
INFO      Feb 05 22:48:04.076483 [access_server]: (do_handle_read): SQLITE_DB client: READING... fd=10
INFO      Feb 05 22:48:04.076503 [access_server]: (do_handle_read): SQLITE_DB client: read blocked
DEBUG     Feb 05 22:48:04.076517 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.076551 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.076569 [GENERIC]: (bind_parameters_to_statement): Binding 5 parameters 0xf75928b8 for query 0x566dbbbc
DEBUG     Feb 05 22:48:04.076584 [GENERIC]: (bind_parameters_to_statement): Query name GET_BULK_LIVEUSERINFO_5
DEBUG     Feb 05 22:48:04.076621 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 4) succeeded
DEBUG     Feb 05 22:48:04.076636 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 5) succeeded
DEBUG     Feb 05 22:48:04.076651 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 2) succeeded
DEBUG     Feb 05 22:48:04.076665 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
DEBUG     Feb 05 22:48:04.076680 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 0) succeeded
DEBUG     Feb 05 22:48:04.076877 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=1 userid=26 attr.starttime=272 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=576244 cycleused_minutes=576244 renewdate='2018-11-19'                upload=21236874038 download=1677698051 cycleupload=21236874038 cycledownload=1677698051
DEBUG     Feb 05 22:48:04.076905 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=2 userid=25 attr.starttime=274 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=386722 cycleused_minutes=386722 renewdate='2018-11-19'                upload=69756631751 download=85404283856 cycleupload=69756631751 cycledownload=85404283856
DEBUG     Feb 05 22:48:04.076927 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=3 userid=9 attr.starttime=292 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=729195 cycleused_minutes=729195 renewdate='2018-10-18'                upload=15735863793 download=32772236487 cycleupload=15735863793 cycledownload=32772236487
DEBUG     Feb 05 22:48:04.076963 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 retrieved: liveuserid=5 userid=25 attr.starttime=392 attr.lastlivetime=11163 isactive=1 policyid=1 accesspolicyid=1                bwpolicyid=0 datatransferpolicyid=0 lastusedtime=1612565104 used_minutes=386722 cycleused_minutes=386722 renewdate='2018-11-19'                upload=69756631751 download=85404283856 cycleupload=69756631751 cycledownload=85404283856
DEBUG     Feb 05 22:48:04.076993 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): SQLITE_DONE
INFO      Feb 05 22:48:04.077008 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): row count: 4
DEBUG     Feb 05 22:48:04.077024 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): returning 0
DEBUG     Feb 05 22:48:04.077038 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077057 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 4
DEBUG     Feb 05 22:48:04.077079 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:576244, cycleused_min:576244, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.077122 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.077137 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 576247
DEBUG     Feb 05 22:48:04.077151 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077170 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.077185 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.077228 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.077243 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 1) succeeded
DEBUG     Feb 05 22:48:04.077323 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077343 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=272
DEBUG     Feb 05 22:48:04.077387 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.077408 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.077423 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.077437 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=576247}
DEBUG     Feb 05 22:48:04.077458 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:576247
DEBUG     Feb 05 22:48:04.077473 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.077486 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.077501 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.077515 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.077560 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.077576 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 576247) succeeded
DEBUG     Feb 05 22:48:04.077591 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 576247) succeeded
DEBUG     Feb 05 22:48:04.077605 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 21236874038) succeeded
DEBUG     Feb 05 22:48:04.077651 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1677698051) succeeded
DEBUG     Feb 05 22:48:04.077667 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 26) succeeded
DEBUG     Feb 05 22:48:04.077681 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077718 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077734 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:386722, cycleused_min:386722, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.077749 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.077764 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 386725
DEBUG     Feb 05 22:48:04.077778 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.077793 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.077807 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.077821 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.077835 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 2) succeeded
DEBUG     Feb 05 22:48:04.077880 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.077895 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=274
DEBUG     Feb 05 22:48:04.077910 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.077924 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.077938 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.077952 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=386725}
DEBUG     Feb 05 22:48:04.077966 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:386725
DEBUG     Feb 05 22:48:04.077980 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.077994 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078008 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078022 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078036 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078051 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078065 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078080 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 69756631751) succeeded
DEBUG     Feb 05 22:48:04.078095 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 85404283856) succeeded
DEBUG     Feb 05 22:48:04.078109 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 25) succeeded
DEBUG     Feb 05 22:48:04.078124 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078151 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078166 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:729195, cycleused_min:729195, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.078181 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.078196 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 729198
DEBUG     Feb 05 22:48:04.078231 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078247 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.078261 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.078275 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.078290 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 3) succeeded
DEBUG     Feb 05 22:48:04.078322 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078337 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=292
DEBUG     Feb 05 22:48:04.078351 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.078365 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.078380 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.078393 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=729198}
DEBUG     Feb 05 22:48:04.078408 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:729198
DEBUG     Feb 05 22:48:04.078422 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.078435 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078449 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078464 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078478 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078493 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 729198) succeeded
DEBUG     Feb 05 22:48:04.078507 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 729198) succeeded
DEBUG     Feb 05 22:48:04.078522 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 15735863793) succeeded
DEBUG     Feb 05 22:48:04.078537 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 32772236487) succeeded
DEBUG     Feb 05 22:48:04.078551 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 9) succeeded
DEBUG     Feb 05 22:48:04.078569 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078596 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078611 [GENERIC]: (update_lastlivetime_periodic): update_lastlivetime_periodic: now_monotonic:11343, used_min:386722, cycleused_min:386722, lastlivetime:11163, diffmin:3.000000
DEBUG     Feb 05 22:48:04.078627 [GENERIC]: (update_lastlivetime_periodic): diffmin : 3.500000
DEBUG     Feb 05 22:48:04.078642 [GENERIC]: (update_lastlivetime_periodic): liveuser used_minutes : 386725
DEBUG     Feb 05 22:48:04.078656 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.078671 [GENERIC]: (bind_parameters_to_statement): Binding 2 parameters 0xf7592858 for query 0x566db9dc
DEBUG     Feb 05 22:48:04.078686 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_PERIODIC
DEBUG     Feb 05 22:48:04.078700 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 11343) succeeded
DEBUG     Feb 05 22:48:04.078715 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_PERIODIC, 5) succeeded
DEBUG     Feb 05 22:48:04.078747 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.078762 [GENERIC]: (get_periodic_liveuser_allowed_status): config session_timeout=4294967295 liveuser starttime=392
DEBUG     Feb 05 22:48:04.078789 [GENERIC]: is_currently_allowed: accesspolicy:1
DEBUG     Feb 05 22:48:04.078803 [GENERIC]: is_currently_allowed: currday:6, hour:22, min:48, currtime:1368
INFO      Feb 05 22:48:04.078817 [GENERIC]: is_currently_allowed: POLICY MATCH. Strategy:'Y'
DEBUG     Feb 05 22:48:04.078831 [GENERIC]: (get_periodic_liveuser_allowed_status): policies->policyid=1, user_acc={used_minutes=386725}
DEBUG     Feb 05 22:48:04.078845 [GENERIC]: has_surfing_time: effective_alloted_min:-11, effective_used_min:386725
DEBUG     Feb 05 22:48:04.078859 [GENERIC]: has_surfing_time: YES
INFO      Feb 05 22:48:04.078873 [GENERIC]: match_surfing_quota: SQuota policy id:1, cycle:80
DEBUG     Feb 05 22:48:04.078887 [GENERIC]: (bind_parameters_to_statement): Binding 6 parameters 0xf7593254 for query 0x566dbd24
DEBUG     Feb 05 22:48:04.078901 [GENERIC]: (bind_parameters_to_statement): Query name UPDATE_LIVEUSER_ACC_PERIODIC
DEBUG     Feb 05 22:48:04.078915 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 1612565284) succeeded
DEBUG     Feb 05 22:48:04.078930 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078944 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 386725) succeeded
DEBUG     Feb 05 22:48:04.078959 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 69756631751) succeeded
DEBUG     Feb 05 22:48:04.078974 [GENERIC]: (check_sqlite_bind_ulong_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 85404283856) succeeded
DEBUG     Feb 05 22:48:04.078988 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_LIVEUSER_ACC_PERIODIC, 25) succeeded
DEBUG     Feb 05 22:48:04.079003 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.079024 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.079039 [GENERIC]: (sqlite_db_handle_request): access_server heartbeat
DEBUG     Feb 05 22:48:04.079054 [GENERIC]: (bind_parameters_to_statement): Binding 5 parameters 0xf75928b8 for query 0x566dbbbc
DEBUG     Feb 05 22:48:04.079069 [GENERIC]: (bind_parameters_to_statement): Query name GET_BULK_LIVEUSERINFO_5
DEBUG     Feb 05 22:48:04.079083 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 4) succeeded
DEBUG     Feb 05 22:48:04.079157 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 5) succeeded
DEBUG     Feb 05 22:48:04.079173 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 2) succeeded
DEBUG     Feb 05 22:48:04.079188 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
DEBUG     Feb 05 22:48:04.079202 [GENERIC]: (check_sqlite_bind_int_result): sqlite3_bind_int(GET_BULK_LIVEUSERINFO_5, 100) succeeded
INFO      Feb 05 22:48:04.079239 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): GET_BULK_LIVEUSERINFO_5 found no entries (sqrs 101)
INFO      Feb 05 22:48:04.079255 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): row count: 0
DEBUG     Feb 05 22:48:04.079269 [GENERIC]: (_sqlite_db_handle_get_bulk_liveuserinfo): returning 0
DEBUG     Feb 05 22:48:04.079283 [GENERIC]: (sqlite_db_submit_response): Request processed res=0

DEBUG     Feb 05 22:48:04.079297 [GENERIC]: (auth_do_periodic_authorization): ludata.count = 0
DEBUG     Feb 05 22:48:04.079311 [GENERIC]: (auth_do_periodic_authorization): found=0
DEBUG     Feb 05 22:48:04.079325 [GENERIC]: (auth_do_periodic_authorization): Periodic Authorization Over, logout_data=(nil)
INFO      Feb 05 22:48:04.079340 [GENERIC]: (do_handle_read): GENERIC server: READING... fd=5
INFO      Feb 05 22:48:04.079361 [GENERIC]: (do_handle_read): GENERIC server: read blocked
INFO      Feb 05 22:48:04.079375 [GENERIC]: subsys_thread_main: GENERIC: waiting for events...
DEBUG     Feb 05 22:48:04.678241 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:48:04.678348 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:48:04.678364 [access_server]: tlvserver_print_request: TLV ID:	148
INFO      Feb 05 22:48:04.678378 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:48:04.678392 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:48:04.678407 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:48:04.678420 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:48:04.678435 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
DEBUG     Feb 05 22:48:04.678456 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x565fa1ad res_handler=(nil) handler_data=(nil)
DEBUG     Feb 05 22:48:04.678479 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:48:04.678494 [access_server]: (append_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:48:04.678509 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:48:04.678524 [access_server]: (append_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:48:04.678538 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:48:04.678553 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
DEBUG     Feb 05 22:48:04.678569 [access_server]: (write_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:48:04.678597 [access_server]: (write_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:48:04.678612 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:48:04.678628 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:48:04.678741 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:48:04.678758 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:48:04.678774 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:48:04.678799 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:48:04.678813 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:48:04.678842 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:48:04.678862 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:48:04.678877 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
ERROR     Feb 05 22:48:28.011726 [CAA]: (CA_epoll_wait): time_to_keep_alive=-1000, after=1612565308, before=1612565262
MESSAGE   Feb 05 22:48:28.011792 [CAA]: (CA_epoll_wait): returning nfds 0
DEBUG     Feb 05 22:48:28.011807 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:48:28.011823 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:48:28.011859 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:48:28.011875 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:48:28.011889 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:48:28.011904 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
DEBUG     Feb 05 22:49:03.682639 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:49:03.682691 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:49:03.682706 [access_server]: tlvserver_print_request: TLV ID:	140
INFO      Feb 05 22:49:03.682720 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:49:03.682734 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:49:03.682748 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:49:03.682762 [access_server]: tlvserver_print_request: ---------------------------------
MESSAGE   Feb 05 22:49:03.682821 [access_server]: tlvserver_process_request: GOT ALERT.EXECUTE_HEARTBEAT
DEBUG     Feb 05 22:49:03.682841 [access_server]: check_timeout_cta_collector: now:11402 last_live:0
MESSAGE   Feb 05 22:49:03.682870 [access_server]: check_timeout_cta_collector: found timeout collector
DEBUG     Feb 05 22:49:03.682891 [access_server]: (do_sendto): send response of 9 bytes to IP: 192.168.199.77 PORT: 6677
DEBUG     Feb 05 22:49:03.683080 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:49:04.467518 [access_server]: tlvserver_handle_request: tlv request received
INFO      Feb 05 22:49:04.467569 [access_server]: tlvserver_print_request: ---------------------------------
INFO      Feb 05 22:49:04.467584 [access_server]: tlvserver_print_request: TLV ID:	148
INFO      Feb 05 22:49:04.467598 [access_server]: tlvserver_print_request: TLV Type:    0
INFO      Feb 05 22:49:04.467612 [access_server]: tlvserver_print_request: TLV Length:	0
INFO      Feb 05 22:49:04.467626 [access_server]: tlvserver_print_request: TLV Cl Res:	0
INFO      Feb 05 22:49:04.467640 [access_server]: tlvserver_print_request: ---------------------------------
DEBUG     Feb 05 22:49:04.467654 [access_server]: tlvserver_process_request: GOT ALERT.EDIR_SYNC
DEBUG     Feb 05 22:49:04.467677 [access_server]: (subsys_submit_request): subsys_name=EDIR_SYNC req_type=0 req_handler=0x565fa1ad res_handler=(nil) handler_data=(nil)
DEBUG     Feb 05 22:49:04.467700 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
DEBUG     Feb 05 22:49:04.467714 [access_server]: (append_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:49:04.467729 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
DEBUG     Feb 05 22:49:04.467743 [access_server]: (append_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:49:04.467757 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
DEBUG     Feb 05 22:49:04.467772 [access_server]: (subsys_submit_request): EDIR_SYNC: request submitted, req_type=0
DEBUG     Feb 05 22:49:04.467788 [access_server]: (write_subsysqueue): acquiring lock 0x56e8c918
DEBUG     Feb 05 22:49:04.467814 [access_server]: (write_subsysqueue): released lock 0x56e8c918
INFO      Feb 05 22:49:04.467829 [access_server]: (write_subsysqueue): EDIR_SYNC CLIENT: written 16 bytes, fd=29 wq=0x56e8a9d0 buf=0x56e8a9d8 offset=0
DEBUG     Feb 05 22:49:04.467845 [access_server]: (do_epoll): Waiting for events
DEBUG     Feb 05 22:49:04.467889 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: event received on fd: 30
DEBUG     Feb 05 22:49:04.467906 [EDIR_SYNC]: handle_server_events: EVENT_READ
INFO      Feb 05 22:49:04.467921 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:49:04.467945 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read 16 bytes, fd=30
DEBUG     Feb 05 22:49:04.467960 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server tlv=0x56e8a778 req_handler=0x565fa1ad type=0 handler_data=(nil) res_handler=(nil)
INFO      Feb 05 22:49:04.467982 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: READING... fd=30
INFO      Feb 05 22:49:04.468002 [EDIR_SYNC]: (do_handle_read): EDIR_SYNC server: read blocked
INFO      Feb 05 22:49:04.468017 [EDIR_SYNC]: subsys_thread_main: EDIR_SYNC: waiting for events...
DEBUG     Feb 05 22:49:13.056039 [CAA]: (CA_epoll_wait): returning 0
MESSAGE   Feb 05 22:49:13.056088 [CAA]: (CA_keep_alive): access_server heartbeat
DEBUG     Feb 05 22:49:13.056106 [CAA]: (CA_keep_alive): Checking connections status
MESSAGE   Feb 05 22:49:13.056122 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
DEBUG     Feb 05 22:49:13.056136 [CAA]: (process_caa_messages): Waiting for CAA events
DEBUG     Feb 05 22:49:13.056151 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
^C
SFV2C4_VM01_SFOS 18.0.4 MR-4# exit
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Device Management 

    1.  Reset to Factory Defaults
    2.  Show Firmware(s)
    3.  Advanced Shell
    4.  Flush Device Reports
    0.  Exit

    Select Menu Number [0-4]: 0
Exit
[H[J
Sophos Firmware Version SFOS 18.0.4 MR-4 

Main Menu 

    1.  Network  Configuration
    2.  System   Configuration
    3.  Route    Configuration 
    4.  Device Console 
    5.  Device Management
    6.  VPN Management
    7.  Shutdown/Reboot Device
    0.  Exit 

    Select Menu Number [0-7]: 0
Exiting Device Menu

Children

0 LuCar Toni over 4 years ago in reply to Antonio Rouqueiro

First of all: SSLVPN requires Login to User Portal and SSLVPN. So you need to check OTP for both facilities.
Cancel
Vote Up +1 Vote Down

Cancel
0 Antonio Rouqueiro over 4 years ago in reply to LuCar Toni

Hi Lucar Toni

This point is already active right from the start in my configuration, because if it was not active I would not be able to login via the SSL VPN client, I simply want to use sophos connect v2 for both types of configuration.

Another problem is that when sophos SSL VPN Client is installed, it is not allowed to install Sophos connect v2, I will have to uninstall sophos SSL VPN in order to install this new version of sophos connect v2, and if I am unable to authenticate with OTP, I won't be able to do.

Below is the print screen of how OTP is configured.
Cancel
Vote Up 0 Vote Down

Cancel