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#