Sophos AD Integration - Authentication proble

Hello Team,

I´m new in the community, I Have a Sophos XG 330 productive one with SFOS 17.5.12 MR-12 and another Sophos XG 330 for backup SFOS 18.0.4 MR-4 both with AD integration working for SSO and L"TP/IPSEC VPN access but when an AD user change the AD password the sophos appliance deny access reporting authentication failure but the user AD authentication works ok. I did everything recomended such logout and login on a workstation, reboot the workstation an login again, but nothing works.

Hope someone could help.

Regards

Marcelo

Parents
  • Why do you want to use L2TP in the first place?

    __________________________________________________________________________________________________________________

  • Was the first option we had for remote workers

  • Wouldnt be Sophos Connect via IPsec / SSLVPN the better approach anyway? L2TP is rather the old scenario. 

    __________________________________________________________________________________________________________________

  • I am testing SSLVPN for a future deploy and facing the same issue with AD authentication

  • Hi ,

    Thank you for contacting the Sophos Community.

    You may check access_server debug events to get more information about auth_fail. Run the below command to put access_server service in debugging.

    ==> Login to SSH > 5. Device Management > 3. Advanced Shell.

    SFOS 18.0.4 MR-4# service access_server:debug -ds nosync

    SFOS 18.0.4 MR-4# tail -f /log/access_server.log

    ==> Try to login to SSL VPN client, and share log output here or in DM to investigate it further. Also please share the SSL VPN client log.

    ==> To stop debugging please run the below command.

    SFOS 18.0.4 MR-4# service access_server:debug -ds nosync

    Thanks,
    Yash Kothari
    Community Support Engineer | Sophos Technical Support
    Sophos Support Videos | Product Documentation | @SophosSupport | Sign up for SMS Alerts
    If a post solves your question, use the 'Verify Answer' link.
  • Here is the output, as client we use L2TP/IPSEC Windows 10.

    DEBUG Feb 25 06:39:49.500435 [access_server]: more_tlv_checks : current tlv len = 4 Sum of length of sub tlv = 8

    DEBUG Feb 25 06:39:49.500439 [access_server]: more_tlv_checks : current tlv len = 29 Sum of length of sub tlv = 41

    DEBUG Feb 25 06:39:49.500442 [access_server]: more_tlv_checks : current tlv len = 24 Sum of length of sub tlv = 69

    DEBUG Feb 25 06:39:49.500446 [access_server]: more_tlv_checks : current tlv len = 20 Sum of length of sub tlv = 93

    DEBUG Feb 25 06:39:49.500449 [access_server]: more_tlv_checks : current tlv len = 14 Sum of length of sub tlv = 111

    DEBUG Feb 25 06:39:49.500453 [access_server]: more_tlv_checks : Valid TLV received, Length of main TLV = 116 Sum of length of sub tlv = 111
    INFO Feb 25 06:39:49.500458 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500462 [access_server]: print_auth_tlv: TLV Type: 0
    INFO Feb 25 06:39:49.500465 [access_server]: print_auth_tlv: TLV Length: 4
    INFO Feb 25 06:39:49.500469 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500472 [access_server]: (process_pam_request): clienttype:'6'
    INFO Feb 25 06:39:49.500476 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500479 [access_server]: print_auth_tlv: TLV Type: 1
    INFO Feb 25 06:39:49.500482 [access_server]: print_auth_tlv: TLV Length: 29
    INFO Feb 25 06:39:49.500486 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500489 [access_server]: (process_pam_request): username:'mlaurenti@xxxx.xxxx.com.ar'
    INFO Feb 25 06:39:49.500492 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500496 [access_server]: print_auth_tlv: TLV Type: 2
    INFO Feb 25 06:39:49.500499 [access_server]: print_auth_tlv: TLV Length: 24
    INFO Feb 25 06:39:49.500502 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500506 [access_server]: (process_pam_request): password: not empty
    INFO Feb 25 06:39:49.500509 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500524 [access_server]: print_auth_tlv: TLV Type: 3
    INFO Feb 25 06:39:49.500528 [access_server]: print_auth_tlv: TLV Length: 20
    INFO Feb 25 06:39:49.500531 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500535 [access_server]: (process_pam_request): CHAP Auth Requested
    DEBUG Feb 25 06:39:49.500538 [access_server]: (process_pam_request): ChapPass: not empty
    INFO Feb 25 06:39:49.500542 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500545 [access_server]: print_auth_tlv: TLV Type: 5
    INFO Feb 25 06:39:49.500548 [access_server]: print_auth_tlv: TLV Length: 14
    INFO Feb 25 06:39:49.500552 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500555 [access_server]: (process_pam_request): ipaddress:'XX.162.40.125'
    DEBUG Feb 25 06:39:49.500562 [access_server]: (authenticate_chap_user): current server:0, auth_client:1
    DEBUG Feb 25 06:39:49.500566 [access_server]: (authenticate_chap_user): current server:1, auth_client:1
    INFO Feb 25 06:39:49.500570 [access_server]: (authenticate_chap_user): Server:1, Local Authentication
    DEBUG Feb 25 06:39:49.500574 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=50 req_handler=0x5666dc51 res_handler=0x5663723c handler_data=0x57708740
    DEBUG Feb 25 06:39:49.500579 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Feb 25 06:39:49.500583 [access_server]: (append_subsysqueue): acquiring lock 0x576979c8
    DEBUG Feb 25 06:39:49.500588 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Feb 25 06:39:49.500592 [access_server]: (append_subsysqueue): released lock 0x576979c8
    INFO Feb 25 06:39:49.500596 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Feb 25 06:39:49.500599 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=50
    DEBUG Feb 25 06:39:49.500603 [access_server]: (write_subsysqueue): acquiring lock 0x576979c8
    DEBUG Feb 25 06:39:49.500611 [access_server]: (write_subsysqueue): released lock 0x576979c8
    INFO Feb 25 06:39:49.500614 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x576a7200 buf=0x576a7208 offset=0
    INFO Feb 25 06:39:49.500620 [access_server]: (authenticate_chap_user): Server:0, ADS Authentication
    DEBUG Feb 25 06:39:49.500621 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
    DEBUG Feb 25 06:39:49.500625 [access_server]: (do_epoll): Waiting for events
    DEBUG Feb 25 06:39:49.500631 [POSTGRES_DB]: handle_server_events: EVENT_READ
    INFO Feb 25 06:39:49.500635 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Feb 25 06:39:49.500641 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
    DEBUG Feb 25 06:39:49.500645 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x576a6ff8 req_handler=0x5666dc51 type=50 handler_data=0x57708740 res_handler=0x5663723c
    DEBUG Feb 25 06:39:49.500651 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.500656 [POSTGRES_DB]: (pg_db_handle_request): L2TP_GETPASS triggers alloc_query_vals()
    DEBUG Feb 25 06:39:49.500659 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
    DEBUG Feb 25 06:39:49.500664 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'L2TP_GETPASS'
    DEBUG Feb 25 06:39:49.500668 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
    DEBUG Feb 25 06:39:49.500671 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500675 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500679 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500997 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'L2TP_GETPASS'
    DEBUG Feb 25 06:39:49.501013 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf5c181c0)
    DEBUG Feb 25 06:39:49.501017 [POSTGRES_DB]: (pg_db_handle_chap_getpass): row count: 0
    ERROR Feb 25 06:39:49.501021 [POSTGRES_DB]: (pg_db_handle_chap_getpass): No rows found
    DEBUG Feb 25 06:39:49.501025 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=-1
    DEBUG Feb 25 06:39:49.501029 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Feb 25 06:39:49.501033 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x576979ec
    DEBUG Feb 25 06:39:49.501037 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Feb 25 06:39:49.501040 [POSTGRES_DB]: (append_subsysqueue): released lock 0x576979ec
    INFO Feb 25 06:39:49.501044 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Feb 25 06:39:49.501047 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=255
    DEBUG Feb 25 06:39:49.501051 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x576979ec
    DEBUG Feb 25 06:39:49.501057 [POSTGRES_DB]: (write_subsysqueue): released lock 0x576979ec
    DEBUG Feb 25 06:39:49.501060 [access_server]: handle_client_events: EVENT_READ
    INFO Feb 25 06:39:49.501061 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x576a70a0 buf=0x576a70a8 offset=0
    INFO Feb 25 06:39:49.501066 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Feb 25 06:39:49.501067 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Feb 25 06:39:49.501071 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
    INFO Feb 25 06:39:49.501072 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
    DEBUG Feb 25 06:39:49.501075 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x576a7158 req_handler=(nil) type=255 handler_data=0x57708740 res_handler=0x5663723c
    INFO Feb 25 06:39:49.501077 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
    DEBUG Feb 25 06:39:49.501081 [access_server]: (authenticate_chap_user): current server:2, auth_client:1
    DEBUG Feb 25 06:39:49.501085 [access_server]: (authenticate_chap_user): authserver_id <= 0, No server left
    ERROR Feb 25 06:39:49.501089 [access_server]: check_auth_result: VPN/SSLVPN/MYACC Authentication Failed
    DEBUG Feb 25 06:39:49.501094 [access_server]: (fill_pam_garner_data): AF_INET ip address 'XXX.162.40.125' is valid
    DEBUG Feb 25 06:39:49.501104 [access_server]: (update_admin_access_table): ip=XXX.162.40.125 clienttype=6
    DEBUG Feb 25 06:39:49.501108 [access_server]: (update_admin_access_table): attempt_allowed: '5', attempts_duration: '60', block_for_minutes: '5'
    DEBUG Feb 25 06:39:49.501113 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501117 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676f928
    DEBUG Feb 25 06:39:49.501122 [access_server]: (bind_parameters_to_statement): Query name IS_ADMIN_IP_EXIST
    DEBUG Feb 25 06:39:49.501132 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(IS_ADMIN_IP_EXIST, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501149 [access_server]: (handle_count_star_query): IS_ADMIN_IP_EXIST retrieved: count = 1
    DEBUG Feb 25 06:39:49.501155 [access_server]: (handle_count_star_query): returning 1
    DEBUG Feb 25 06:39:49.501160 [access_server]: (sqlite_db_submit_response): Request processed res=1

    DEBUG Feb 25 06:39:49.501163 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501167 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676fb6c
    DEBUG Feb 25 06:39:49.501171 [access_server]: (bind_parameters_to_statement): Query name GET_ADMINACCESS_INFO
    DEBUG Feb 25 06:39:49.501176 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(GET_ADMINACCESS_INFO, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501191 [access_server]: (_sqlite_db_handle_get_adminaccess_info): GET_ADMINACCESS_INFO retrieved: lastfail=1717762 timeleft=60 counter=1 blocking=0
    DEBUG Feb 25 06:39:49.501197 [access_server]: (_sqlite_db_handle_get_adminaccess_info): returning 0
    DEBUG Feb 25 06:39:49.501201 [access_server]: (sqlite_db_submit_response): Request processed res=0

    MESSAGE Feb 25 06:39:49.501204 [access_server]: (update_admin_access_table): # Admin user authentication fail from IP XXX.162.40.125
    DEBUG Feb 25 06:39:49.501208 [access_server]: (bind_parameters_to_statement): Binding 5 parameters 0xffea1980 for query 0x5676fd4c
    DEBUG Feb 25 06:39:49.501212 [access_server]: (bind_parameters_to_statement): Query name UPDATE_ADMINACCESS
    DEBUG Feb 25 06:39:49.501217 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1718090) succeeded
    DEBUG Feb 25 06:39:49.501220 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 60) succeeded
    DEBUG Feb 25 06:39:49.501224 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1) succeeded
    DEBUG Feb 25 06:39:49.501227 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 0) succeeded
    DEBUG Feb 25 06:39:49.501232 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(UPDATE_ADMINACCESS, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501236 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501253 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Feb 25 06:39:49.501257 [access_server]: (send_pam_response): resp_code=3, clienttype=6, message='Login failed. Invalid user name/password. Please contact the administrator. '
    DEBUG Feb 25 06:39:49.501261 [access_server]: send_pam_response: message:'Login failed. Invalid user name/password. Please contact the administrator. ', len:76, data:'Login failed. Invalid user name/password. Please contact the administrator. '
    DEBUG Feb 25 06:39:49.501265 [access_server]: (send_response_authtlv): Packetlen:80
    DEBUG Feb 25 06:39:49.501270 [access_server]: (do_sendto): send response of 80 bytes to IP: 127.0.0.1 PORT: 34852
    DEBUG Feb 25 06:39:49.501274 [access_server]: (do_sendto): pktinfo: ifindex: 0, local address: 127.0.0.1
    DEBUG Feb 25 06:39:49.501288 [access_server]: (send_response_authtlv): Bytes sent:80, Buf len:80
    DEBUG Feb 25 06:39:49.501292 [access_server]: free_session_data: session_data=0x57708740
    INFO Feb 25 06:39:49.501296 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Feb 25 06:39:49.501301 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
    DEBUG Feb 25 06:39:49.501305 [access_server]: (do_epoll): Waiting for events
    DEBUG Feb 25 06:39:50.586613 [CAA]: (CA_epoll_wait): returning 0
    MESSAGE Feb 25 06:39:50.586630 [CAA]: (CA_keep_alive): access_server heartbeat
    DEBUG Feb 25 06:39:50.586635 [CAA]: (CA_keep_alive): Checking connections status
    MESSAGE Feb 25 06:39:50.586639 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
    DEBUG Feb 25 06:39:50.586643 [CAA]: (process_caa_messages): Waiting for CAA events
    DEBUG Feb 25 06:39:50.586646 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
    DEBUG Feb 25 06:39:58.536217 [access_server]: (handle_client): 11 bytes from IP: XXX.211.1.196, PORT: 65402
    DEBUG Feb 25 06:39:58.536229 [access_server]: (handle_client): pktinfo: ifindex: 5, local address: XXX.211.254.244

Reply
  • Here is the output, as client we use L2TP/IPSEC Windows 10.

    DEBUG Feb 25 06:39:49.500435 [access_server]: more_tlv_checks : current tlv len = 4 Sum of length of sub tlv = 8

    DEBUG Feb 25 06:39:49.500439 [access_server]: more_tlv_checks : current tlv len = 29 Sum of length of sub tlv = 41

    DEBUG Feb 25 06:39:49.500442 [access_server]: more_tlv_checks : current tlv len = 24 Sum of length of sub tlv = 69

    DEBUG Feb 25 06:39:49.500446 [access_server]: more_tlv_checks : current tlv len = 20 Sum of length of sub tlv = 93

    DEBUG Feb 25 06:39:49.500449 [access_server]: more_tlv_checks : current tlv len = 14 Sum of length of sub tlv = 111

    DEBUG Feb 25 06:39:49.500453 [access_server]: more_tlv_checks : Valid TLV received, Length of main TLV = 116 Sum of length of sub tlv = 111
    INFO Feb 25 06:39:49.500458 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500462 [access_server]: print_auth_tlv: TLV Type: 0
    INFO Feb 25 06:39:49.500465 [access_server]: print_auth_tlv: TLV Length: 4
    INFO Feb 25 06:39:49.500469 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500472 [access_server]: (process_pam_request): clienttype:'6'
    INFO Feb 25 06:39:49.500476 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500479 [access_server]: print_auth_tlv: TLV Type: 1
    INFO Feb 25 06:39:49.500482 [access_server]: print_auth_tlv: TLV Length: 29
    INFO Feb 25 06:39:49.500486 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500489 [access_server]: (process_pam_request): username:'mlaurenti@xxxx.xxxx.com.ar'
    INFO Feb 25 06:39:49.500492 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500496 [access_server]: print_auth_tlv: TLV Type: 2
    INFO Feb 25 06:39:49.500499 [access_server]: print_auth_tlv: TLV Length: 24
    INFO Feb 25 06:39:49.500502 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500506 [access_server]: (process_pam_request): password: not empty
    INFO Feb 25 06:39:49.500509 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500524 [access_server]: print_auth_tlv: TLV Type: 3
    INFO Feb 25 06:39:49.500528 [access_server]: print_auth_tlv: TLV Length: 20
    INFO Feb 25 06:39:49.500531 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500535 [access_server]: (process_pam_request): CHAP Auth Requested
    DEBUG Feb 25 06:39:49.500538 [access_server]: (process_pam_request): ChapPass: not empty
    INFO Feb 25 06:39:49.500542 [access_server]: print_auth_tlv: -----------------AUTH_TLV--------
    INFO Feb 25 06:39:49.500545 [access_server]: print_auth_tlv: TLV Type: 5
    INFO Feb 25 06:39:49.500548 [access_server]: print_auth_tlv: TLV Length: 14
    INFO Feb 25 06:39:49.500552 [access_server]: print_auth_tlv: ---------------------------------
    DEBUG Feb 25 06:39:49.500555 [access_server]: (process_pam_request): ipaddress:'XX.162.40.125'
    DEBUG Feb 25 06:39:49.500562 [access_server]: (authenticate_chap_user): current server:0, auth_client:1
    DEBUG Feb 25 06:39:49.500566 [access_server]: (authenticate_chap_user): current server:1, auth_client:1
    INFO Feb 25 06:39:49.500570 [access_server]: (authenticate_chap_user): Server:1, Local Authentication
    DEBUG Feb 25 06:39:49.500574 [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=50 req_handler=0x5666dc51 res_handler=0x5663723c handler_data=0x57708740
    DEBUG Feb 25 06:39:49.500579 [access_server]: (append_subsysqueue): : CLIENT, datasize: 16
    DEBUG Feb 25 06:39:49.500583 [access_server]: (append_subsysqueue): acquiring lock 0x576979c8
    DEBUG Feb 25 06:39:49.500588 [access_server]: (append_subsysqueue): : CLIENT, remlen: 160
    DEBUG Feb 25 06:39:49.500592 [access_server]: (append_subsysqueue): released lock 0x576979c8
    INFO Feb 25 06:39:49.500596 [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue
    DEBUG Feb 25 06:39:49.500599 [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=50
    DEBUG Feb 25 06:39:49.500603 [access_server]: (write_subsysqueue): acquiring lock 0x576979c8
    DEBUG Feb 25 06:39:49.500611 [access_server]: (write_subsysqueue): released lock 0x576979c8
    INFO Feb 25 06:39:49.500614 [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x576a7200 buf=0x576a7208 offset=0
    INFO Feb 25 06:39:49.500620 [access_server]: (authenticate_chap_user): Server:0, ADS Authentication
    DEBUG Feb 25 06:39:49.500621 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9
    DEBUG Feb 25 06:39:49.500625 [access_server]: (do_epoll): Waiting for events
    DEBUG Feb 25 06:39:49.500631 [POSTGRES_DB]: handle_server_events: EVENT_READ
    INFO Feb 25 06:39:49.500635 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Feb 25 06:39:49.500641 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9
    DEBUG Feb 25 06:39:49.500645 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x576a6ff8 req_handler=0x5666dc51 type=50 handler_data=0x57708740 res_handler=0x5663723c
    DEBUG Feb 25 06:39:49.500651 [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.500656 [POSTGRES_DB]: (pg_db_handle_request): L2TP_GETPASS triggers alloc_query_vals()
    DEBUG Feb 25 06:39:49.500659 [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c
    DEBUG Feb 25 06:39:49.500664 [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'L2TP_GETPASS'
    DEBUG Feb 25 06:39:49.500668 [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking
    DEBUG Feb 25 06:39:49.500671 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500675 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500679 [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2]: 'mlaurenti@xxxx.xxxx.com.ar'
    DEBUG Feb 25 06:39:49.500997 [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'L2TP_GETPASS'
    DEBUG Feb 25 06:39:49.501013 [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf5c181c0)
    DEBUG Feb 25 06:39:49.501017 [POSTGRES_DB]: (pg_db_handle_chap_getpass): row count: 0
    ERROR Feb 25 06:39:49.501021 [POSTGRES_DB]: (pg_db_handle_chap_getpass): No rows found
    DEBUG Feb 25 06:39:49.501025 [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=-1
    DEBUG Feb 25 06:39:49.501029 [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16
    DEBUG Feb 25 06:39:49.501033 [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x576979ec
    DEBUG Feb 25 06:39:49.501037 [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160
    DEBUG Feb 25 06:39:49.501040 [POSTGRES_DB]: (append_subsysqueue): released lock 0x576979ec
    INFO Feb 25 06:39:49.501044 [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue
    DEBUG Feb 25 06:39:49.501047 [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=255
    DEBUG Feb 25 06:39:49.501051 [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x576979ec
    DEBUG Feb 25 06:39:49.501057 [POSTGRES_DB]: (write_subsysqueue): released lock 0x576979ec
    DEBUG Feb 25 06:39:49.501060 [access_server]: handle_client_events: EVENT_READ
    INFO Feb 25 06:39:49.501061 [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x576a70a0 buf=0x576a70a8 offset=0
    INFO Feb 25 06:39:49.501066 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Feb 25 06:39:49.501067 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9
    INFO Feb 25 06:39:49.501071 [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8
    INFO Feb 25 06:39:49.501072 [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked
    DEBUG Feb 25 06:39:49.501075 [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x576a7158 req_handler=(nil) type=255 handler_data=0x57708740 res_handler=0x5663723c
    INFO Feb 25 06:39:49.501077 [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events...
    DEBUG Feb 25 06:39:49.501081 [access_server]: (authenticate_chap_user): current server:2, auth_client:1
    DEBUG Feb 25 06:39:49.501085 [access_server]: (authenticate_chap_user): authserver_id <= 0, No server left
    ERROR Feb 25 06:39:49.501089 [access_server]: check_auth_result: VPN/SSLVPN/MYACC Authentication Failed
    DEBUG Feb 25 06:39:49.501094 [access_server]: (fill_pam_garner_data): AF_INET ip address 'XXX.162.40.125' is valid
    DEBUG Feb 25 06:39:49.501104 [access_server]: (update_admin_access_table): ip=XXX.162.40.125 clienttype=6
    DEBUG Feb 25 06:39:49.501108 [access_server]: (update_admin_access_table): attempt_allowed: '5', attempts_duration: '60', block_for_minutes: '5'
    DEBUG Feb 25 06:39:49.501113 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501117 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676f928
    DEBUG Feb 25 06:39:49.501122 [access_server]: (bind_parameters_to_statement): Query name IS_ADMIN_IP_EXIST
    DEBUG Feb 25 06:39:49.501132 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(IS_ADMIN_IP_EXIST, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501149 [access_server]: (handle_count_star_query): IS_ADMIN_IP_EXIST retrieved: count = 1
    DEBUG Feb 25 06:39:49.501155 [access_server]: (handle_count_star_query): returning 1
    DEBUG Feb 25 06:39:49.501160 [access_server]: (sqlite_db_submit_response): Request processed res=1

    DEBUG Feb 25 06:39:49.501163 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501167 [access_server]: (bind_parameters_to_statement): Binding 1 parameters 0xffea0f08 for query 0x5676fb6c
    DEBUG Feb 25 06:39:49.501171 [access_server]: (bind_parameters_to_statement): Query name GET_ADMINACCESS_INFO
    DEBUG Feb 25 06:39:49.501176 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(GET_ADMINACCESS_INFO, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501191 [access_server]: (_sqlite_db_handle_get_adminaccess_info): GET_ADMINACCESS_INFO retrieved: lastfail=1717762 timeleft=60 counter=1 blocking=0
    DEBUG Feb 25 06:39:49.501197 [access_server]: (_sqlite_db_handle_get_adminaccess_info): returning 0
    DEBUG Feb 25 06:39:49.501201 [access_server]: (sqlite_db_submit_response): Request processed res=0

    MESSAGE Feb 25 06:39:49.501204 [access_server]: (update_admin_access_table): # Admin user authentication fail from IP XXX.162.40.125
    DEBUG Feb 25 06:39:49.501208 [access_server]: (bind_parameters_to_statement): Binding 5 parameters 0xffea1980 for query 0x5676fd4c
    DEBUG Feb 25 06:39:49.501212 [access_server]: (bind_parameters_to_statement): Query name UPDATE_ADMINACCESS
    DEBUG Feb 25 06:39:49.501217 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1718090) succeeded
    DEBUG Feb 25 06:39:49.501220 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 60) succeeded
    DEBUG Feb 25 06:39:49.501224 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 1) succeeded
    DEBUG Feb 25 06:39:49.501227 [access_server]: (check_sqlite_bind_int_result): sqlite3_bind_int(UPDATE_ADMINACCESS, 0) succeeded
    DEBUG Feb 25 06:39:49.501232 [access_server]: (check_sqlite_bind_text_result): sqlite3_bind_text(UPDATE_ADMINACCESS, XXX.162.40.125) succeeded
    DEBUG Feb 25 06:39:49.501236 [access_server]: (sqlite_db_handle_request): access_server heartbeat
    DEBUG Feb 25 06:39:49.501253 [access_server]: (sqlite_db_submit_response): Request processed res=0

    DEBUG Feb 25 06:39:49.501257 [access_server]: (send_pam_response): resp_code=3, clienttype=6, message='Login failed. Invalid user name/password. Please contact the administrator. '
    DEBUG Feb 25 06:39:49.501261 [access_server]: send_pam_response: message:'Login failed. Invalid user name/password. Please contact the administrator. ', len:76, data:'Login failed. Invalid user name/password. Please contact the administrator. '
    DEBUG Feb 25 06:39:49.501265 [access_server]: (send_response_authtlv): Packetlen:80
    DEBUG Feb 25 06:39:49.501270 [access_server]: (do_sendto): send response of 80 bytes to IP: 127.0.0.1 PORT: 34852
    DEBUG Feb 25 06:39:49.501274 [access_server]: (do_sendto): pktinfo: ifindex: 0, local address: 127.0.0.1
    DEBUG Feb 25 06:39:49.501288 [access_server]: (send_response_authtlv): Bytes sent:80, Buf len:80
    DEBUG Feb 25 06:39:49.501292 [access_server]: free_session_data: session_data=0x57708740
    INFO Feb 25 06:39:49.501296 [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8
    INFO Feb 25 06:39:49.501301 [access_server]: (do_handle_read): POSTGRES_DB client: read blocked
    DEBUG Feb 25 06:39:49.501305 [access_server]: (do_epoll): Waiting for events
    DEBUG Feb 25 06:39:50.586613 [CAA]: (CA_epoll_wait): returning 0
    MESSAGE Feb 25 06:39:50.586630 [CAA]: (CA_keep_alive): access_server heartbeat
    DEBUG Feb 25 06:39:50.586635 [CAA]: (CA_keep_alive): Checking connections status
    MESSAGE Feb 25 06:39:50.586639 [CAA]: (CA_keep_alive): Next CA batch in 45 seconds
    DEBUG Feb 25 06:39:50.586643 [CAA]: (process_caa_messages): Waiting for CAA events
    DEBUG Feb 25 06:39:50.586646 [CAA]: (CA_epoll_wait): timeout=45000, time_to_keep_alive=45000
    DEBUG Feb 25 06:39:58.536217 [access_server]: (handle_client): 11 bytes from IP: XXX.211.1.196, PORT: 65402
    DEBUG Feb 25 06:39:58.536229 [access_server]: (handle_client): pktinfo: ifindex: 5, local address: XXX.211.254.244

Children