I am facing an issue with setting up Duo for the Sophos XG firewall. I know Sophos has not built out their dedicated API to work with Duo yet (need to resort to using Sophos UTM application protection in Duo), but I have confirmed that this is working successfully with another client running an XG firewall and Active Directory domain controller running the Duo Auth Proxy. In my setup, I am able to get a push notification approval when signing into VPN, after supplying correct username and password, I get the push, I approve it, it goes back to firewall and then gets kicked back with invalid UN/PW in the logs, which I am unsure what is causing that. The VPN prompt comes back with blank username and password for me to try again, even though I just put the creds in correctly and approved my Duo push notification.
I have gone through the following:
- ensured auth proxy configuration is good, validated good,
- disabled OTP MFA on the XG
- made sure test user is coming through as an AD imported user, the group (Duo_VPN) they are in is present on the XG firewall, and they are confirmed as a member in the group in both XG, and AD
- setup RADIUS server in XG firewall, and have tested good, meaning secrets match up good, and my test user in Duo is successfully getting a test push notification
- Sophos XG logs show the test auth coming in, getting approved by the server running Duo Auth Proxy (does not matter if Auth Proxy is installed on DC or another server),
DEBUG Oct 24 13:42:32.085276Z [RADIUS_AUTH]: (cb_authenticate_user): Authentication OK for User: 'testuser'
DEBUG Oct 24 13:42:32.085302Z [RADIUS_AUTH]: (radiusauth_authenticate_user_finish): RADIUS_AUTH: User Authenticated with Server: '192.168.10.135:18120'
and then there is a 2nd auth prompt in the logs of the XG at the same exact time, that show 'Login failed. Invalid user name/password. Please contact the administrator. '
DEBUG Oct 24 13:42:32.086875Z [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x570cd258 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c53e4
ERROR Oct 24 13:42:32.086879Z [access_server]: handle_pam_authorization: VPN/SSLVPN/MYACC Authorization Failed, result_code=1
DEBUG Oct 24 13:42:32.086886Z [access_server]: (fill_pam_garner_data): AF_INET ip address '8.221.10.19' is valid
DEBUG Oct 24 13:42:32.086897Z [access_server]: (send_pam_response): resp_code=3, clienttype=13, message='Login failed. Invalid user name/password. Please contact the administrator. '
DEBUG Oct 24 13:42:32.086902Z [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 Oct 24 13:42:32.086905Z [access_server]: (send_response_authtlv): Packetlen:80
I have gone so far as to move the Auth Proxy to a different server, and also initially spent a lot of time trying to make this work with an AD group 'DUO_VPN', which I peeled out, so no AD group being used, and just let the user be a member of the default XG 'Open Group', it still does not make any difference, the same issue plays out where it says bad username/password invalid EVEN after I get a successful Duo push, and approve! The logs below show the issue without any special group being used, user being in 'Open Group'. I have also edited the external, internal IP's being used, and domain suffix for privacy purposes.
DEBUG Oct 24 13:42:23.670208Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:25.671685Z [access_server]: (do_epoll): No event to process DEBUG Oct 24 13:42:25.671702Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:27.671952Z [access_server]: (do_epoll): No event to process DEBUG Oct 24 13:42:27.671971Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:28.235114Z [access_server]: (handle_client): 128 bytes from IP: 127.0.0.1, PORT: 58865 DEBUG Oct 24 13:42:28.235127Z [access_server]: (handle_client): pktinfo: ifindex: 1, local address: 127.0.0.1 DEBUG Oct 24 13:42:28.235133Z [access_server]: (handle_client): Received request length in TLV = 128. Received bytes on socket = 128. tlv_jump = 0. INFO Oct 24 13:42:28.235137Z [access_server]: process_request: Request Code:91 DEBUG Oct 24 13:42:28.235141Z [access_server]: more_tlv_checks : current tlv len = 4, Sum of length of sub tlv = 8 DEBUG Oct 24 13:42:28.235145Z [access_server]: more_tlv_checks : current tlv len = 8, Sum of length of sub tlv = 20 DEBUG Oct 24 13:42:28.235148Z [access_server]: more_tlv_checks : current tlv len = 13, Sum of length of sub tlv = 37 DEBUG Oct 24 13:42:28.235151Z [access_server]: more_tlv_checks : current tlv len = 60, Sum of length of sub tlv = 101 DEBUG Oct 24 13:42:28.235154Z [access_server]: more_tlv_checks : current tlv len = 12, Sum of length of sub tlv = 117 DEBUG Oct 24 13:42:28.235158Z [access_server]: more_tlv_checks : current tlv len = 2, Sum of length of sub tlv = 123 DEBUG Oct 24 13:42:28.235161Z [access_server]: more_tlv_checks : Valid TLV received, Length of main TLV = 128, Sum of length of sub tlv = 123 INFO Oct 24 13:42:28.235166Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235169Z [access_server]: print_auth_tlv: TLV Type: 0 INFO Oct 24 13:42:28.235172Z [access_server]: print_auth_tlv: TLV Length: 4 INFO Oct 24 13:42:28.235175Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235178Z [access_server]: (process_pam_request): clienttype:'13' INFO Oct 24 13:42:28.235181Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235184Z [access_server]: print_auth_tlv: TLV Type: 1 INFO Oct 24 13:42:28.235187Z [access_server]: print_auth_tlv: TLV Length: 8 INFO Oct 24 13:42:28.235207Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235211Z [access_server]: (process_pam_request): username:'testuser' INFO Oct 24 13:42:28.235214Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235216Z [access_server]: print_auth_tlv: TLV Type: 2 INFO Oct 24 13:42:28.235219Z [access_server]: print_auth_tlv: TLV Length: 13 INFO Oct 24 13:42:28.235222Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235225Z [access_server]: (process_pam_request): password: not empty INFO Oct 24 13:42:28.235228Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235231Z [access_server]: print_auth_tlv: TLV Type: 13 INFO Oct 24 13:42:28.235234Z [access_server]: print_auth_tlv: TLV Length: 60 INFO Oct 24 13:42:28.235237Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235240Z [access_server]: (process_pam_request): fingerprint:'47:96:c9:22:54:2d:ff:4d:70:af:f7:7c:41:5a:2d:c7:95:44:30:85' INFO Oct 24 13:42:28.235244Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235247Z [access_server]: print_auth_tlv: TLV Type: 5 INFO Oct 24 13:42:28.235250Z [access_server]: print_auth_tlv: TLV Length: 12 INFO Oct 24 13:42:28.235252Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235255Z [access_server]: (process_pam_request): ipaddress:'8.221.10.19' INFO Oct 24 13:42:28.235262Z [access_server]: print_auth_tlv: -----------------AUTH_TLV-------- INFO Oct 24 13:42:28.235265Z [access_server]: print_auth_tlv: TLV Type: 14 INFO Oct 24 13:42:28.235268Z [access_server]: print_auth_tlv: TLV Length: 2 INFO Oct 24 13:42:28.235271Z [access_server]: print_auth_tlv: --------------------------------- DEBUG Oct 24 13:42:28.235274Z [access_server]: (process_pam_request): remote port 53719 DEBUG Oct 24 13:42:28.235279Z [access_server]: (lc_utf8_bytes): lowercase = 'testuser' DEBUG Oct 24 13:42:28.235285Z [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=35 req_handler=0x565e9b17 res_handler=0x565c86de handler_data=0x5715c3c0 DEBUG Oct 24 13:42:28.235290Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:28.235293Z [access_server]: (append_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:28.235296Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:28.235300Z [access_server]: (append_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:28.235303Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:28.235306Z [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=35 DEBUG Oct 24 13:42:28.235310Z [access_server]: (write_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:28.235317Z [access_server]: (write_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:28.235320Z [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x570cd300 buf=0x570cd308 offset=0 DEBUG Oct 24 13:42:28.235324Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:28.235329Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9 DEBUG Oct 24 13:42:28.235338Z [POSTGRES_DB]: handle_server_events: EVENT_READ INFO Oct 24 13:42:28.235341Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:28.235348Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9 DEBUG Oct 24 13:42:28.235351Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x570cd0f8 req_handler=0x565e9b17 type=35 handler_data=0x5715c3c0 res_handler=0x565c86de DEBUG Oct 24 13:42:28.235356Z [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat DEBUG Oct 24 13:42:28.235371Z [POSTGRES_DB]: (pg_db_handle_request): AUTHENTICATE_GUEST_USER triggers alloc_query_vals() DEBUG Oct 24 13:42:28.235375Z [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c DEBUG Oct 24 13:42:28.235379Z [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'AUTHENTICATE_GUEST_USER' DEBUG Oct 24 13:42:28.235383Z [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking DEBUG Oct 24 13:42:28.235386Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'testuser' DEBUG Oct 24 13:42:28.235577Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'AUTHENTICATE_GUEST_USER' DEBUG Oct 24 13:42:28.235585Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf7031a80) DEBUG Oct 24 13:42:28.235590Z [POSTGRES_DB]: pg_db_handle_authenticate_guest_user: row count: 0 DEBUG Oct 24 13:42:28.235593Z [POSTGRES_DB]: pg_db_handle_authenticate_guest_user: No rows found DEBUG Oct 24 13:42:28.235597Z [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0 DEBUG Oct 24 13:42:28.235600Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16 DEBUG Oct 24 13:42:28.235603Z [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:28.235606Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160 DEBUG Oct 24 13:42:28.235609Z [POSTGRES_DB]: (append_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:28.235612Z [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:28.235616Z [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0 DEBUG Oct 24 13:42:28.235619Z [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:28.235625Z [POSTGRES_DB]: (write_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:28.235628Z [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x570cd1a0 buf=0x570cd1a8 offset=0 DEBUG Oct 24 13:42:28.235628Z [access_server]: handle_client_events: EVENT_READ INFO Oct 24 13:42:28.235632Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:28.235634Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 INFO Oct 24 13:42:28.235637Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked INFO Oct 24 13:42:28.235639Z [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8 INFO Oct 24 13:42:28.235641Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events... DEBUG Oct 24 13:42:28.235643Z [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x570cd258 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c86de DEBUG Oct 24 13:42:28.235648Z [access_server]: (subsys_submit_request): subsys_name=OTP_AUTH req_type=0 req_handler=0x56625a9a res_handler=0x565c7b33 handler_data=0x5715c3c0 DEBUG Oct 24 13:42:28.235652Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:28.235655Z [access_server]: (append_subsysqueue): acquiring lock 0x57140378 DEBUG Oct 24 13:42:28.235661Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:28.235664Z [access_server]: (append_subsysqueue): released lock 0x57140378 INFO Oct 24 13:42:28.235667Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:28.235670Z [access_server]: (subsys_submit_request): OTP_AUTH: request submitted, req_type=0 DEBUG Oct 24 13:42:28.235674Z [access_server]: (write_subsysqueue): acquiring lock 0x57140378 DEBUG Oct 24 13:42:28.235680Z [access_server]: (write_subsysqueue): released lock 0x57140378 INFO Oct 24 13:42:28.235683Z [access_server]: (write_subsysqueue): OTP_AUTH CLIENT: written 16 bytes, fd=17 wq=0x57140170 buf=0x57140178 offset=0 DEBUG Oct 24 13:42:28.235684Z [OTP_AUTH]: subsys_thread_main: OTP_AUTH: event received on fd: 18 INFO Oct 24 13:42:28.235687Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 DEBUG Oct 24 13:42:28.235697Z [OTP_AUTH]: handle_server_events: EVENT_READ INFO Oct 24 13:42:28.235698Z [access_server]: (do_handle_read): POSTGRES_DB client: read blocked INFO Oct 24 13:42:28.235700Z [OTP_AUTH]: (do_handle_read): OTP_AUTH server: READING... fd=18 DEBUG Oct 24 13:42:28.235701Z [access_server]: (do_epoll): Waiting for events INFO Oct 24 13:42:28.235706Z [OTP_AUTH]: (do_handle_read): OTP_AUTH server: read 16 bytes, fd=18 DEBUG Oct 24 13:42:28.235709Z [OTP_AUTH]: (do_handle_read): OTP_AUTH server tlv=0x57140958 req_handler=0x56625a9a type=0 handler_data=0x5715c3c0 res_handler=0x565c7b33 DEBUG Oct 24 13:42:28.235713Z [OTP_AUTH]: (otp_handle_prepare_authentication_request): OTP prepare authentication for user testuser DEBUG Oct 24 13:42:28.235717Z [OTP_AUTH]: (append_subsysqueue): : SERVER, datasize: 16 DEBUG Oct 24 13:42:28.235721Z [OTP_AUTH]: (append_subsysqueue): acquiring lock 0x5714039c DEBUG Oct 24 13:42:28.235724Z [OTP_AUTH]: (append_subsysqueue): : SERVER, remlen: 160 DEBUG Oct 24 13:42:28.235727Z [OTP_AUTH]: (append_subsysqueue): released lock 0x5714039c INFO Oct 24 13:42:28.235731Z [OTP_AUTH]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:28.235734Z [OTP_AUTH]: subsys_submit_response: OTP_AUTH: response submitted, res_type=0 DEBUG Oct 24 13:42:28.235737Z [OTP_AUTH]: (write_subsysqueue): acquiring lock 0x5714039c DEBUG Oct 24 13:42:28.235742Z [OTP_AUTH]: (write_subsysqueue): released lock 0x5714039c DEBUG Oct 24 13:42:28.235743Z [access_server]: handle_client_events: EVENT_READ INFO Oct 24 13:42:28.235745Z [OTP_AUTH]: (write_subsysqueue): OTP_AUTH SERVER: written 16 bytes, fd=18 wq=0x57140600 buf=0x57140608 offset=0 INFO Oct 24 13:42:28.235747Z [access_server]: (do_handle_read): OTP_AUTH client: READING... fd=17 INFO Oct 24 13:42:28.235749Z [OTP_AUTH]: (do_handle_read): OTP_AUTH server: READING... fd=18 INFO Oct 24 13:42:28.235751Z [access_server]: (do_handle_read): OTP_AUTH client: read 16 bytes, fd=17 INFO Oct 24 13:42:28.235753Z [OTP_AUTH]: (do_handle_read): OTP_AUTH server: read blocked DEBUG Oct 24 13:42:28.235755Z [access_server]: (do_handle_read): OTP_AUTH client tlv=0x571400c8 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c7b33 INFO Oct 24 13:42:28.235756Z [OTP_AUTH]: subsys_thread_main: OTP_AUTH: waiting for events... DEBUG Oct 24 13:42:28.235759Z [access_server]: (authenticate_user): current server:0, auth_client:2 INFO Oct 24 13:42:28.235763Z [access_server]: authenticate_user: Server:0, RADIUS Authentication DEBUG Oct 24 13:42:28.235766Z [access_server]: (subsys_submit_request): subsys_name=RADIUS_AUTH req_type=0 req_handler=0x566060c7 res_handler=0x565c7b33 handler_data=0x5715c3c0 DEBUG Oct 24 13:42:28.235770Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:28.235773Z [access_server]: (append_subsysqueue): acquiring lock 0x5715a1f8 DEBUG Oct 24 13:42:28.235776Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:28.235780Z [access_server]: (append_subsysqueue): released lock 0x5715a1f8 INFO Oct 24 13:42:28.235783Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:28.235786Z [access_server]: (subsys_submit_request): RADIUS_AUTH: request submitted, req_type=0 DEBUG Oct 24 13:42:28.235789Z [access_server]: (write_subsysqueue): acquiring lock 0x5715a1f8 DEBUG Oct 24 13:42:28.235795Z [access_server]: (write_subsysqueue): released lock 0x5715a1f8 INFO Oct 24 13:42:28.235798Z [access_server]: (write_subsysqueue): RADIUS_AUTH CLIENT: written 16 bytes, fd=32 wq=0x57149250 buf=0x57149258 offset=0 DEBUG Oct 24 13:42:28.235799Z [RADIUS_AUTH]: subsys_thread_main: RADIUS_AUTH: event received on fd: 33 INFO Oct 24 13:42:28.235802Z [access_server]: (do_handle_read): OTP_AUTH client: READING... fd=17 DEBUG Oct 24 13:42:28.235803Z [RADIUS_AUTH]: handle_server_events: EVENT_READ INFO Oct 24 13:42:28.235812Z [access_server]: (do_handle_read): OTP_AUTH client: read blocked INFO Oct 24 13:42:28.235813Z [RADIUS_AUTH]: (do_handle_read): RADIUS_AUTH server: READING... fd=33 DEBUG Oct 24 13:42:28.235816Z [access_server]: (do_epoll): Waiting for events INFO Oct 24 13:42:28.235818Z [RADIUS_AUTH]: (do_handle_read): RADIUS_AUTH server: read 16 bytes, fd=33 DEBUG Oct 24 13:42:28.235822Z [RADIUS_AUTH]: (do_handle_read): RADIUS_AUTH server tlv=0x57149428 req_handler=0x566060c7 type=0 handler_data=0x5715c3c0 res_handler=0x565c7b33 DEBUG Oct 24 13:42:28.235826Z [RADIUS_AUTH]: (radiusauth_handle_authrequest): RADIUS_AUTH: Authenticating with Server: '192.168.10.135:18120' DEBUG Oct 24 13:42:28.235837Z [RADIUS_AUTH]: (radiusauth_prepare_request): service type set to: 8 DEBUG Oct 24 13:42:28.235842Z [RADIUS_AUTH]: (radiusauth_prepare_request): username set to 'testuser' DEBUG Oct 24 13:42:28.236003Z [RADIUS_AUTH]: (radiusauth_authenticate_user): Authentication pending for User: 'testuser' INFO Oct 24 13:42:28.236010Z [RADIUS_AUTH]: (do_handle_read): RADIUS_AUTH server: READING... fd=33 INFO Oct 24 13:42:28.236014Z [RADIUS_AUTH]: (do_handle_read): RADIUS_AUTH server: read blocked INFO Oct 24 13:42:28.236017Z [RADIUS_AUTH]: subsys_thread_main: RADIUS_AUTH: waiting for events... DEBUG Oct 24 13:42:30.237107Z [access_server]: (do_epoll): No event to process DEBUG Oct 24 13:42:30.237131Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:32.085276Z [RADIUS_AUTH]: (cb_authenticate_user): Authentication OK for User: 'testuser' DEBUG Oct 24 13:42:32.085302Z [RADIUS_AUTH]: (radiusauth_authenticate_user_finish): RADIUS_AUTH: User Authenticated with Server: '192.168.10.135:18120' DEBUG Oct 24 13:42:32.085307Z [RADIUS_AUTH]: (append_subsysqueue): : SERVER, datasize: 16 DEBUG Oct 24 13:42:32.085312Z [RADIUS_AUTH]: (append_subsysqueue): acquiring lock 0x5715a21c DEBUG Oct 24 13:42:32.085316Z [RADIUS_AUTH]: (append_subsysqueue): : SERVER, remlen: 160 DEBUG Oct 24 13:42:32.085322Z [RADIUS_AUTH]: (append_subsysqueue): released lock 0x5715a21c INFO Oct 24 13:42:32.085325Z [RADIUS_AUTH]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.085329Z [RADIUS_AUTH]: subsys_submit_response: RADIUS_AUTH: response submitted, res_type=0 DEBUG Oct 24 13:42:32.085334Z [RADIUS_AUTH]: (write_subsysqueue): acquiring lock 0x5715a21c DEBUG Oct 24 13:42:32.085342Z [RADIUS_AUTH]: (write_subsysqueue): released lock 0x5715a21c INFO Oct 24 13:42:32.085346Z [RADIUS_AUTH]: (write_subsysqueue): RADIUS_AUTH SERVER: written 16 bytes, fd=33 wq=0x57158df0 buf=0x57158df8 offset=0 DEBUG Oct 24 13:42:32.085347Z [access_server]: handle_client_events: EVENT_READ INFO Oct 24 13:42:32.085358Z [access_server]: (do_handle_read): RADIUS_AUTH client: READING... fd=32 INFO Oct 24 13:42:32.085364Z [access_server]: (do_handle_read): RADIUS_AUTH client: read 16 bytes, fd=32 DEBUG Oct 24 13:42:32.085368Z [access_server]: (do_handle_read): RADIUS_AUTH client tlv=0x571491a8 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c7b33 DEBUG Oct 24 13:42:32.085372Z [access_server]: (authenticate_user): current server:1, auth_client:2 DEBUG Oct 24 13:42:32.085376Z [access_server]: authenticate_user: SUCCESS || current_server >= MAX_LIMIT DEBUG Oct 24 13:42:32.085379Z [access_server]: (is_local_auth): current_server = 0, auth_client = 2, authserver_id = 4, local_authserver_id = 1 SUCCESS Oct 24 13:42:32.085383Z [access_server]: (check_auth_result): user 'testuser@contoso.local'(backend) Authenticated with server id '4' DEBUG Oct 24 13:42:32.085388Z [access_server]: (check_auth_result): Setting authserverid 4 for user testuser@contoso.local DEBUG Oct 24 13:42:32.085392Z [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=96 req_handler=0x565e9b17 res_handler=(nil) handler_data=0x5715bd50 DEBUG Oct 24 13:42:32.085412Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:32.085416Z [access_server]: (append_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.085419Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:32.085422Z [access_server]: (append_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:32.085425Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.085428Z [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=96 DEBUG Oct 24 13:42:32.085431Z [access_server]: (write_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.085437Z [access_server]: (write_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:32.085440Z [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x570cd300 buf=0x570cd308 offset=0 DEBUG Oct 24 13:42:32.085441Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9 DEBUG Oct 24 13:42:32.085444Z [access_server]: check_auth_result: Authentication Successful, clienttype=13 auth_client=2 DEBUG Oct 24 13:42:32.085446Z [POSTGRES_DB]: handle_server_events: EVENT_READ DEBUG Oct 24 13:42:32.085448Z [access_server]: (pg_db_handle_request): access_server heartbeat INFO Oct 24 13:42:32.085449Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 DEBUG Oct 24 13:42:32.085453Z [access_server]: (pg_db_handle_request): IS_CRT_FINGERPRINT triggers alloc_query_vals() INFO Oct 24 13:42:32.085455Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9 DEBUG Oct 24 13:42:32.085456Z [access_server]: (alloc_query_vals): using query_vals on stack 0xffccfcac DEBUG Oct 24 13:42:32.085459Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x570cd0f8 req_handler=0x565e9b17 type=96 handler_data=0x5715bd50 res_handler=(nil) DEBUG Oct 24 13:42:32.085461Z [access_server]: (pg_db_process_prepq_async): executing command 'IS_CRT_FINGERPRINT' DEBUG Oct 24 13:42:32.085463Z [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat DEBUG Oct 24 13:42:32.085465Z [access_server]: (pg_db_process_prepq_async): PG's socket (fd 7) is NON-blocking DEBUG Oct 24 13:42:32.085467Z [POSTGRES_DB]: (pg_db_handle_request): SET_USER_AUTHSERVERID triggers alloc_query_vals() DEBUG Oct 24 13:42:32.085468Z [access_server]: (pg_db_process_prepq_async): param_value[0]: 'testuser@contoso.local' DEBUG Oct 24 13:42:32.085471Z [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c DEBUG Oct 24 13:42:32.085472Z [access_server]: (pg_db_process_prepq_async): param_value[1]: '47:96:c9:22:54:2d:ff:4d:70:af:f7:7c:41:5a:2d:c7:95:44:30:85' DEBUG Oct 24 13:42:32.085475Z [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'SET_USER_AUTHSERVERID' DEBUG Oct 24 13:42:32.085478Z [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking DEBUG Oct 24 13:42:32.085482Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0] length=4: 4 DEBUG Oct 24 13:42:32.085485Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1]: 'testuser@contoso.local' DEBUG Oct 24 13:42:32.085719Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'SET_USER_AUTHSERVERID' DEBUG Oct 24 13:42:32.085725Z [access_server]: (pg_db_get_async_prepq_result): retrieving PGresult of 'IS_CRT_FINGERPRINT' DEBUG Oct 24 13:42:32.085728Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf7031a80) DEBUG Oct 24 13:42:32.085733Z [access_server]: (pg_db_get_async_prepq_result): returning PGresult 1 (0x5715bee0) DEBUG Oct 24 13:42:32.085735Z [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0 ERROR Oct 24 13:42:32.085738Z [access_server]: pg_db_handle_check_crt_fingerprint: row count: 1 value 1 INFO Oct 24 13:42:32.085739Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 DEBUG Oct 24 13:42:32.085743Z [access_server]: pg_db_submit_response: Request Processed: res_type=0 INFO Oct 24 13:42:32.085756Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked DEBUG Oct 24 13:42:32.085757Z [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=0 req_handler=0x565e9b17 res_handler=0x565c6565 handler_data=0x5715c3c0 INFO Oct 24 13:42:32.085760Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events... DEBUG Oct 24 13:42:32.085761Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:32.085764Z [access_server]: (append_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.085768Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:32.085771Z [access_server]: (append_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:32.085774Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.085777Z [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=0 DEBUG Oct 24 13:42:32.085780Z [access_server]: (write_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.085786Z [access_server]: (write_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:32.085789Z [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x570cd300 buf=0x570cd308 offset=0 INFO Oct 24 13:42:32.085793Z [access_server]: (do_handle_read): RADIUS_AUTH client: READING... fd=32 INFO Oct 24 13:42:32.085799Z [access_server]: (do_handle_read): RADIUS_AUTH client: read blocked DEBUG Oct 24 13:42:32.085802Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:32.085808Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9 DEBUG Oct 24 13:42:32.085813Z [POSTGRES_DB]: handle_server_events: EVENT_READ INFO Oct 24 13:42:32.085816Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:32.085821Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9 DEBUG Oct 24 13:42:32.085824Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x570cd0f8 req_handler=0x565e9b17 type=0 handler_data=0x5715c3c0 res_handler=0x565c6565 DEBUG Oct 24 13:42:32.085828Z [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat DEBUG Oct 24 13:42:32.085831Z [POSTGRES_DB]: (pg_db_handle_request): GET_USERINFO triggers alloc_query_vals() DEBUG Oct 24 13:42:32.085835Z [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c DEBUG Oct 24 13:42:32.085838Z [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'GET_USERINFO' DEBUG Oct 24 13:42:32.085841Z [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking DEBUG Oct 24 13:42:32.085844Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'testuser@contoso.local' DEBUG Oct 24 13:42:32.085847Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[1] length=4: 1 DEBUG Oct 24 13:42:32.085851Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[2] length=4: 2 DEBUG Oct 24 13:42:32.085854Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[3] length=4: 5 DEBUG Oct 24 13:42:32.085857Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[4] length=4: 8 DEBUG Oct 24 13:42:32.086158Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'GET_USERINFO' DEBUG Oct 24 13:42:32.086166Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf7031a80) DEBUG Oct 24 13:42:32.086170Z [POSTGRES_DB]: pg_db_handle_get_userinfo: row count: 0 DEBUG Oct 24 13:42:32.086173Z [POSTGRES_DB]: (pg_db_handle_get_userinfo): pg_server 0x570bb058 DEBUG Oct 24 13:42:32.086176Z [POSTGRES_DB]: (pg_db_handle_get_userinfo): No rows found, integration=1, groupname=NULL, clienttype=13 DEBUG Oct 24 13:42:32.086181Z [POSTGRES_DB]: (get_groupname_attr): called DEBUG Oct 24 13:42:32.086193Z [POSTGRES_DB]: (get_group_list_by_server_type): auth_data.type = 4 INFO Oct 24 13:42:32.086197Z [POSTGRES_DB]: (get_group_list_by_server_type): not doing anything as session's auth_data is empty! DEBUG Oct 24 13:42:32.086200Z [POSTGRES_DB]: (get_group_list_by_server_type): returning matches 0 DEBUG Oct 24 13:42:32.086203Z [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat DEBUG Oct 24 13:42:32.086208Z [POSTGRES_DB]: (pg_db_handle_request): GET_GROUPINFO_BYID triggers alloc_query_vals() DEBUG Oct 24 13:42:32.086212Z [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fdc0c DEBUG Oct 24 13:42:32.086215Z [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'GET_GROUPINFO_BYID' DEBUG Oct 24 13:42:32.086218Z [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking DEBUG Oct 24 13:42:32.086222Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0] length=4: 1 DEBUG Oct 24 13:42:32.086413Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'GET_GROUPINFO_BYID' DEBUG Oct 24 13:42:32.086420Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf7032140) DEBUG Oct 24 13:42:32.086424Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: row count: 1 DEBUG Oct 24 13:42:32.086427Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'name', value:'Open Group' DEBUG Oct 24 13:42:32.086432Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'groupid', value:'1' DEBUG Oct 24 13:42:32.086435Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'surfingquotapolicyid', value:'1' DEBUG Oct 24 13:42:32.086439Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'webfilterid', value:'1' DEBUG Oct 24 13:42:32.086442Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'appfilterid', value:'1' DEBUG Oct 24 13:42:32.086445Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'accesspolicyid', value:'1' DEBUG Oct 24 13:42:32.086448Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'bwpolicyid', value:'' DEBUG Oct 24 13:42:32.086451Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'datatransferpolicyid', value:'' DEBUG Oct 24 13:42:32.086454Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'macbinding', value:'2' DEBUG Oct 24 13:42:32.086457Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'ipallocation', value:'1' DEBUG Oct 24 13:42:32.086460Z [POSTGRES_DB]: pg_db_get_userinfo_from_group: column:'allotedminutes', value:'-11' DEBUG Oct 24 13:42:32.086464Z [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0 DEBUG Oct 24 13:42:32.086469Z [POSTGRES_DB]: pg_db_handle_get_userinfo: no rows found, returning 0 DEBUG Oct 24 13:42:32.086472Z [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0 DEBUG Oct 24 13:42:32.086475Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16 DEBUG Oct 24 13:42:32.086478Z [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:32.086481Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160 DEBUG Oct 24 13:42:32.086485Z [POSTGRES_DB]: (append_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:32.086488Z [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.086491Z [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0 DEBUG Oct 24 13:42:32.086494Z [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:32.086500Z [POSTGRES_DB]: (write_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:32.086503Z [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x570cd1a0 buf=0x570cd1a8 offset=0 INFO Oct 24 13:42:32.086507Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:32.086511Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked INFO Oct 24 13:42:32.086514Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events... DEBUG Oct 24 13:42:32.086520Z [access_server]: handle_client_events: EVENT_READ INFO Oct 24 13:42:32.086529Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 INFO Oct 24 13:42:32.086534Z [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8 DEBUG Oct 24 13:42:32.086537Z [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x570cd258 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c6565 DEBUG Oct 24 13:42:32.086542Z [access_server]: (subsys_submit_request): subsys_name=POSTGRES_DB req_type=41 req_handler=0x565e9b17 res_handler=0x565c53e4 handler_data=0x5715c3c0 DEBUG Oct 24 13:42:32.086545Z [access_server]: (append_subsysqueue): : CLIENT, datasize: 16 DEBUG Oct 24 13:42:32.086549Z [access_server]: (append_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.086552Z [access_server]: (append_subsysqueue): : CLIENT, remlen: 160 DEBUG Oct 24 13:42:32.086555Z [access_server]: (append_subsysqueue): released lock 0x570ccde8 INFO Oct 24 13:42:32.086558Z [access_server]: (append_subsysqueue): CLIENT: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.086561Z [access_server]: (subsys_submit_request): POSTGRES_DB: request submitted, req_type=41 DEBUG Oct 24 13:42:32.086564Z [access_server]: (write_subsysqueue): acquiring lock 0x570ccde8 DEBUG Oct 24 13:42:32.086569Z [access_server]: (write_subsysqueue): released lock 0x570ccde8 DEBUG Oct 24 13:42:32.086570Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: event received on fd: 9 INFO Oct 24 13:42:32.086572Z [access_server]: (write_subsysqueue): POSTGRES_DB CLIENT: written 16 bytes, fd=8 wq=0x570cd300 buf=0x570cd308 offset=0 DEBUG Oct 24 13:42:32.086574Z [POSTGRES_DB]: handle_server_events: EVENT_READ INFO Oct 24 13:42:32.086576Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 INFO Oct 24 13:42:32.086578Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:32.086580Z [access_server]: (do_handle_read): POSTGRES_DB client: read blocked INFO Oct 24 13:42:32.086583Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read 16 bytes, fd=9 DEBUG Oct 24 13:42:32.086584Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:32.086586Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server tlv=0x570cd0f8 req_handler=0x565e9b17 type=41 handler_data=0x5715c3c0 res_handler=0x565c53e4 DEBUG Oct 24 13:42:32.086590Z [POSTGRES_DB]: (pg_db_handle_request): access_server heartbeat DEBUG Oct 24 13:42:32.086593Z [POSTGRES_DB]: (pg_db_handle_request): SSLVPN_NEW_USER triggers alloc_query_vals() DEBUG Oct 24 13:42:32.086597Z [POSTGRES_DB]: (alloc_query_vals): using query_vals on stack 0xf72fe62c DEBUG Oct 24 13:42:32.086600Z [POSTGRES_DB]: (pg_db_process_prepq_async): executing command 'SSLVPN_NEW_USER' DEBUG Oct 24 13:42:32.086603Z [POSTGRES_DB]: (pg_db_process_prepq_async): PG's socket (fd 6) is NON-blocking DEBUG Oct 24 13:42:32.086606Z [POSTGRES_DB]: (pg_db_process_prepq_async): param_value[0]: 'testuser@contoso.local' DEBUG Oct 24 13:42:32.086805Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): retrieving PGresult of 'SSLVPN_NEW_USER' DEBUG Oct 24 13:42:32.086810Z [POSTGRES_DB]: (pg_db_get_async_prepq_result): returning PGresult 1 (0xf7032140) DEBUG Oct 24 13:42:32.086814Z [POSTGRES_DB]: pg_db_handle_xauth_user: row count: 1 DEBUG Oct 24 13:42:32.086817Z [POSTGRES_DB]: pg_db_handle_xauth_user: column:'count', value:'0' DEBUG Oct 24 13:42:32.086821Z [POSTGRES_DB]: pg_db_handle_xauth_user: result_code=1 DEBUG Oct 24 13:42:32.086824Z [POSTGRES_DB]: pg_db_submit_response: Request Processed: res_type=0 DEBUG Oct 24 13:42:32.086827Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, datasize: 16 DEBUG Oct 24 13:42:32.086830Z [POSTGRES_DB]: (append_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:32.086833Z [POSTGRES_DB]: (append_subsysqueue): : SERVER, remlen: 160 DEBUG Oct 24 13:42:32.086842Z [POSTGRES_DB]: (append_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:32.086845Z [POSTGRES_DB]: (append_subsysqueue): SERVER: '16' bytes appended to subsys queue DEBUG Oct 24 13:42:32.086848Z [POSTGRES_DB]: subsys_submit_response: POSTGRES_DB: response submitted, res_type=0 DEBUG Oct 24 13:42:32.086851Z [POSTGRES_DB]: (write_subsysqueue): acquiring lock 0x570cce0c DEBUG Oct 24 13:42:32.086856Z [POSTGRES_DB]: (write_subsysqueue): released lock 0x570cce0c INFO Oct 24 13:42:32.086859Z [POSTGRES_DB]: (write_subsysqueue): POSTGRES_DB SERVER: written 16 bytes, fd=9 wq=0x570cd1a0 buf=0x570cd1a8 offset=0 DEBUG Oct 24 13:42:32.086860Z [access_server]: handle_client_events: EVENT_READ INFO Oct 24 13:42:32.086863Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: READING... fd=9 INFO Oct 24 13:42:32.086866Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 INFO Oct 24 13:42:32.086868Z [POSTGRES_DB]: (do_handle_read): POSTGRES_DB server: read blocked INFO Oct 24 13:42:32.086871Z [access_server]: (do_handle_read): POSTGRES_DB client: read 16 bytes, fd=8 INFO Oct 24 13:42:32.086871Z [POSTGRES_DB]: subsys_thread_main: POSTGRES_DB: waiting for events... DEBUG Oct 24 13:42:32.086875Z [access_server]: (do_handle_read): POSTGRES_DB client tlv=0x570cd258 req_handler=(nil) type=0 handler_data=0x5715c3c0 res_handler=0x565c53e4 ERROR Oct 24 13:42:32.086879Z [access_server]: handle_pam_authorization: VPN/SSLVPN/MYACC Authorization Failed, result_code=1 DEBUG Oct 24 13:42:32.086886Z [access_server]: (fill_pam_garner_data): AF_INET ip address '8.221.10.19' is valid DEBUG Oct 24 13:42:32.086897Z [access_server]: (send_pam_response): resp_code=3, clienttype=13, message='Login failed. Invalid user name/password. Please contact the administrator. ' DEBUG Oct 24 13:42:32.086902Z [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 Oct 24 13:42:32.086905Z [access_server]: (send_response_authtlv): Packetlen:80 DEBUG Oct 24 13:42:32.086910Z [access_server]: (do_sendto): send response of 80 bytes to IP: 127.0.0.1 PORT: 58865 DEBUG Oct 24 13:42:32.086914Z [access_server]: (do_sendto): pktinfo: ifindex: 0, local address: 127.0.0.1 DEBUG Oct 24 13:42:32.086928Z [access_server]: (send_response_authtlv): Bytes sent:80, Buf len:80 DEBUG Oct 24 13:42:32.086932Z [access_server]: free_session_data: session_data=0x5715c3c0 DEBUG Oct 24 13:42:32.086936Z [access_server]: (reset_user_info): resetting user_info 0xf7031a80 DEBUG Oct 24 13:42:32.086939Z [access_server]: (free_session_data): freeing user_info 0xf7031a80 INFO Oct 24 13:42:32.086944Z [access_server]: (do_handle_read): POSTGRES_DB client: READING... fd=8 INFO Oct 24 13:42:32.086947Z [access_server]: (do_handle_read): POSTGRES_DB client: read blocked DEBUG Oct 24 13:42:32.086951Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:34.088129Z [access_server]: (do_epoll): No event to process DEBUG Oct 24 13:42:34.088147Z [access_server]: (do_epoll): Waiting for events DEBUG Oct 24 13:42:36.090065Z [access_server]: (do_epoll): No event to process DEBUG Oct 24 13:42:36.090084Z [access_server]: (do_epoll): Waiting for events ^C XG230_WP01_SFOS 18.5.3 MR-3-Build408#
This thread was automatically locked due to age.
