```bash 2023-05-09T12:22:29,841 DEBUG [pool-6-thread-199] metastore.ObjectStore: 0 entries retrieved using SQL in 0.70832ms 2023-05-09T12:22:29,841 INFO [pool-6-thread-199] metastore.ObjectStore: Dropping database hive.test along with all tables 2023-05-09T12:22:29,841 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 2, isActive = true at: org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1095) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) 2023-05-09T12:22:29,841 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true at: org.apache.hadoop.hive.metastore.ObjectStore.getMDatabase(ObjectStore.java:968) org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1098) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2023-05-09T12:22:29,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true at: org.apache.hadoop.hive.metastore.ObjectStore.getMDatabase(ObjectStore.java:976) org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1098) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2023-05-09T12:22:29,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Executing listDatabaseGrants 2023-05-09T12:22:29,844 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 3, isActive = true at: org.apache.hadoop.hive.metastore.ObjectStore.listDatabaseGrants(ObjectStore.java:6754) org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1101) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2023-05-09T12:22:29,846 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 2, isactive true at: org.apache.hadoop.hive.metastore.ObjectStore.listDatabaseGrants(ObjectStore.java:6768) org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1101) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2023-05-09T12:22:29,846 DEBUG [pool-6-thread-199] metastore.ObjectStore: Done retrieving all objects for listDatabaseGrants 2023-05-09T12:22:29,850 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 1, isactive true at: org.apache.hadoop.hive.metastore.ObjectStore.dropDatabase(ObjectStore.java:1107) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) 2023-05-09T12:22:29,850 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 0, isactive true at: java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) 2023-05-09T12:22:29,852 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@7ce3e4dc 2023-05-09T12:22:29,853 DEBUG [pool-6-thread-199] metastore.ReplChangeManager: Repl policy is not set for database 2023-05-09T12:22:29,853 DEBUG [pool-6-thread-199] utils.FileUtils: deleting s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test 2023-05-09T12:22:29,853 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test (test); needEmptyDirectory=false 2023-05-09T12:22:29,853 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: S3GetFileStatus s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test 2023-05-09T12:22:29,853 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: HEAD test with change tracker null 2023-05-09T12:22:29,854 DEBUG [pool-6-thread-199] impl.LoggingAuditor: [228] 7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015 Executing op_get_file_status with {action_http_head_request 'test' size=0, mutating=false}; https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 2023-05-09T12:22:29,854 DEBUG [pool-6-thread-199] amazonaws.request: Sending Request: HEAD https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: signsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsign 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: Request: HEAD https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWSCredentials: com.amazonaws.auth.BasicAWSCredentials@421e2a2f 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: super.getServiceName: s3-outposts 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 Canonical Request: '"HEAD /test amz-sdk-invocation-id:b32e30e6-2856-4c59-3560-6a1bb3eee8b8 amz-sdk-request:ttl=20230509T122549Z;attempt=1;max=21 amz-sdk-retry:0/0/500 content-type:application/octet-stream host:ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com referer:https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 user-agent:Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy x-amz-content-sha256:UNSIGNED-PAYLOAD x-amz-date:20230509T122229Z amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date UNSIGNED-PAYLOAD" 2023-05-09T12:22:29,855 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230509T122229Z 20230509/ap-northeast-1/s3-outposts/aws4_request 22e157f2c83cfa883210d0303f2847fc19590cfa2d38082e20c11e7c716632d6" 2023-05-09T12:22:29,856 DEBUG [pool-6-thread-199] protocol.RequestAddCookies: CookieSpec selected: default 2023-05-09T12:22:29,856 DEBUG [pool-6-thread-199] protocol.RequestAuthCache: Auth cache not set in the context 2023-05-09T12:22:29,856 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 0 of 96; total allocated: 0 of 96] 2023-05-09T12:22:29,856 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection leased: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:29,856 DEBUG [pool-6-thread-199] execchain.MainClientExec: Opening connection {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443 2023-05-09T12:22:29,898 DEBUG [pool-6-thread-199] conn.DefaultHttpClientConnectionOperator: Connecting to ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com/10.0.200.251:443 2023-05-09T12:22:29,898 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: Connecting socket to ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com/10.0.200.251:443 with timeout 5000 2023-05-09T12:22:29,898 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: Enabled protocols: [TLSv1.3, TLSv1.2] 2023-05-09T12:22:29,898 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: Enabled cipher suites:[TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256, TLS_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] 2023-05-09T12:22:29,899 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: Starting handshake 2023-05-09T12:22:29,909 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: Secure session established 2023-05-09T12:22:29,909 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: negotiated protocol: TLSv1.2 2023-05-09T12:22:29,909 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 2023-05-09T12:22:29,909 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: peer principal: CN=*.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:29,909 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: peer alternative names: [*.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com] 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] ssl.SSLConnectionSocketFactory: issuer principal: CN=Amazon RSA 2048 M01, O=Amazon, C=US 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] conn.DefaultHttpClientConnectionOperator: Connection established 10.0.201.132:56960<->10.0.200.251:443 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] execchain.MainClientExec: Executing request HEAD /test HTTP/1.1 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] execchain.MainClientExec: Proxy auth state: UNCHALLENGED 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> HEAD /test HTTP/1.1 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-invocation-id: b32e30e6-2856-4c59-3560-6a1bb3eee8b8 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-request: ttl=20230509T122549Z;attempt=1;max=21 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-retry: 0/0/500 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=52d4effb7b88b1af7b738b726643a58bca0ad7400df800a3a3cec1c76c84e756 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Type: application/octet-stream 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Referer: https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> x-amz-content-sha256: UNSIGNED-PAYLOAD 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> X-Amz-Date: 20230509T122229Z 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Connection: Keep-Alive 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "HEAD /test HTTP/1.1[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-invocation-id: b32e30e6-2856-4c59-3560-6a1bb3eee8b8[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-request: ttl=20230509T122549Z;attempt=1;max=21[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-retry: 0/0/500[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=52d4effb7b88b1af7b738b726643a58bca0ad7400df800a3a3cec1c76c84e756[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Type: application/octet-stream[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Referer: https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "x-amz-content-sha256: UNSIGNED-PAYLOAD[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "X-Amz-Date: 20230509T122229Z[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 2023-05-09T12:22:29,910 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "HTTP/1.1 404 Not Found[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Type: application/xml[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Server: AmazonS3[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-id-2: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-request-id: 7C8E69DF2A6DDA0B[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Date: Tue, 09 May 2023 12:22:30 GMT[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "[\r][\n]" 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << HTTP/1.1 404 Not Found 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Type: application/xml 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Server: AmazonS3 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-id-2: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-request-id: 7C8E69DF2A6DDA0B 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Date: Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] execchain.MainClientExec: Connection can be kept alive for 60000 MILLISECONDS 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443] can be kept alive for 60.0 seconds 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 0 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection released: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] retry.ClockSkewAdjuster: Reported server date (from 'Date' header): Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,212 DEBUG [pool-6-thread-199] amazonaws.request: Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 7C8E69DF2A6DDA0B; S3 Extended Request ID: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd; Proxy: null), S3 Extended Request ID: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd 2023-05-09T12:22:30,213 DEBUG [pool-6-thread-199] amazonaws.latency: ServiceName=[Amazon S3], AWSErrorCode=[404 Not Found], StatusCode=[404], ServiceEndpoint=[https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com], Exception=[com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 7C8E69DF2A6DDA0B; S3 Extended Request ID: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd; Proxy: null), S3 Extended Request ID: nql8Ke+GLYHCx2wqQUgJhU5G4PK51gTPA6AaEaMv3hg4d4vD8SR4HXhoxpdVZVP3jsN2u8IrvawhYXfRRE3fmAxvqkCSRRwd], RequestType=[GetObjectMetadataRequest], AWSRequestID=[7C8E69DF2A6DDA0B], HttpClientPoolPendingCount=0, RetryCapacityConsumed=0, HttpClientPoolAvailableCount=0, RequestCount=1, Exception=1, HttpClientPoolLeasedCount=0, ClientExecuteTime=[358.894], HttpClientSendRequestTime=[0.62], HttpRequestTime=[356.587], ApiCallLatency=[358.59], RequestSigningTime=[1.108], CredentialsRequestTime=[0.008, 0.004], HttpClientReceiveResponseTime=[301.341], 2023-05-09T12:22:30,213 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: LIST List ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3:/test/ delimiter=/ keys=2 requester pays=false 2023-05-09T12:22:30,213 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Starting: LIST 2023-05-09T12:22:30,213 DEBUG [pool-6-thread-199] impl.LoggingAuditor: [228] 7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015 Executing op_get_file_status with {object_list_request 'test/' size=2, mutating=false}; https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] amazonaws.request: Sending Request: GET https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com / 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] auth.AWS4Signer: signsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsign 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] auth.AWS4Signer: Request: GET https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com / 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWSCredentials: com.amazonaws.auth.BasicAWSCredentials@2f2d4207 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] auth.AWS4Signer: super.getServiceName: s3-outposts 2023-05-09T12:22:30,214 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 Canonical Request: '"GET / delimiter=%2F&fetch-owner=false&list-type=2&max-keys=2&prefix=test%2F amz-sdk-invocation-id:0a62486d-eb27-3988-681f-e16c864bdcf4 amz-sdk-request:ttl=20230509T122550Z;attempt=1;max=21 amz-sdk-retry:0/0/500 content-type:application/octet-stream host:ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com referer:https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 user-agent:Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy x-amz-content-sha256:UNSIGNED-PAYLOAD x-amz-date:20230509T122230Z amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date UNSIGNED-PAYLOAD" 2023-05-09T12:22:30,215 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230509T122230Z 20230509/ap-northeast-1/s3-outposts/aws4_request 52bf3400697f8b5bef62533f2c3d3c76e021988643f0b73c79ee7c4a2753436d" 2023-05-09T12:22:30,215 DEBUG [pool-6-thread-199] protocol.RequestAddCookies: CookieSpec selected: default 2023-05-09T12:22:30,215 DEBUG [pool-6-thread-199] protocol.RequestAuthCache: Auth cache not set in the context 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection leased: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] execchain.MainClientExec: Executing request GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] execchain.MainClientExec: Proxy auth state: UNCHALLENGED 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-invocation-id: 0a62486d-eb27-3988-681f-e16c864bdcf4 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-retry: 0/0/500 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=185563473e35440003fe8a3663c5c9570f5cddc211a8ae8063ecf64e31c9dd51 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Type: application/octet-stream 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Referer: https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> x-amz-content-sha256: UNSIGNED-PAYLOAD 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> X-Amz-Date: 20230509T122230Z 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Length: 0 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Connection: Keep-Alive 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-invocation-id: 0a62486d-eb27-3988-681f-e16c864bdcf4[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-retry: 0/0/500[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=185563473e35440003fe8a3663c5c9570f5cddc211a8ae8063ecf64e31c9dd51[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Type: application/octet-stream[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Referer: https://audit.example.org/hadoop/1/op_get_file_status/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015/?op=op_get_file_status&p1=test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000015&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634949853[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "x-amz-content-sha256: UNSIGNED-PAYLOAD[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "X-Amz-Date: 20230509T122230Z[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Length: 0[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 2023-05-09T12:22:30,216 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "HTTP/1.1 200 OK[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Type: application/xml[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Server: AmazonS3[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-bucket-region: ap-northeast-1[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-id-2: 5e/Y09HvX+3VKaegIYgnZ4FSLhCdK6mc5cS/zIgAQOItP/Hir0s64wiu0rOhza1WI8HXJ8j7VDXLS1iXWLQzyLJ2SwcsELlC[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-request-id: 5D91C27638EE2E13[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Date: Tue, 09 May 2023 12:22:30 GMT[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Length: 442[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "[\r][\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "<?xml version="1.0" encoding="UTF-8"?>[\n]" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "<ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Contents><ETag>&quot;d41d8cd98f00b204e9800998ecf8427e&quot;</ETag><Key>test/</Key><LastModified>2023-05-09T10:37:06.472Z</LastModified><Size>0</Size><StorageClass>OUTPOSTS</StorageClass></Contents><Delimiter>/</Delimiter><IsTruncated>false</IsTruncated><KeyCount>1</KeyCount><MaxKeys>2</MaxKeys><Prefix>test/</Prefix></ListBucketResult>" 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << HTTP/1.1 200 OK 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Type: application/xml 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Server: AmazonS3 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-bucket-region: ap-northeast-1 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-id-2: 5e/Y09HvX+3VKaegIYgnZ4FSLhCdK6mc5cS/zIgAQOItP/Hir0s64wiu0rOhza1WI8HXJ8j7VDXLS1iXWLQzyLJ2SwcsELlC 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-request-id: 5D91C27638EE2E13 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Date: Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Length: 442 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] execchain.MainClientExec: Connection can be kept alive for 60000 MILLISECONDS 2023-05-09T12:22:30,280 DEBUG [pool-6-thread-199] retry.ClockSkewAdjuster: Reported server date (from 'Date' header): Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,282 DEBUG [pool-6-thread-199] transform.XmlResponsesSaxParser: Sanitizing XML document destined for handler class com.amazonaws.services.s3.model.transform.XmlResponsesSaxParser$ListObjectsV2Handler 2023-05-09T12:22:30,282 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443] can be kept alive for 60.0 seconds 2023-05-09T12:22:30,282 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 0 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection released: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] transform.XmlResponsesSaxParser: Parsing XML response document with handler: class com.amazonaws.services.s3.model.transform.XmlResponsesSaxParser$ListObjectsV2Handler 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] amazonaws.request: Received successful response: 200, AWS Request ID: 5D91C27638EE2E13 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] amazonaws.requestId: x-amzn-RequestId: not available 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Request ID: 5D91C27638EE2E13 2023-05-09T12:22:30,283 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Extended Request ID: 5e/Y09HvX+3VKaegIYgnZ4FSLhCdK6mc5cS/zIgAQOItP/Hir0s64wiu0rOhza1WI8HXJ8j7VDXLS1iXWLQzyLJ2SwcsELlC 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] amazonaws.latency: ServiceName=[Amazon S3], StatusCode=[200], ServiceEndpoint=[https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com], RequestType=[ListObjectsV2Request], AWSRequestID=[5D91C27638EE2E13], HttpClientPoolPendingCount=0, RetryCapacityConsumed=0, HttpClientPoolAvailableCount=1, RequestCount=1, HttpClientPoolLeasedCount=0, ResponseProcessingTime=[2.635], ClientExecuteTime=[69.962], HttpClientSendRequestTime=[0.608], HttpRequestTime=[65.348], ApiCallLatency=[69.542], RequestSigningTime=[0.943], CredentialsRequestTime=[0.009, 0.006], HttpClientReceiveResponseTime=[64.028], 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: LIST: duration 0:00.071s 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found path as directory (with /) 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Prefix count = 0; object count=1 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Summary: test/ 0 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Getting path status for s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test (test); needEmptyDirectory=true 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: S3GetFileStatus s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: HEAD test with change tracker null 2023-05-09T12:22:30,284 DEBUG [pool-6-thread-199] impl.LoggingAuditor: [228] 7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016 Executing op_delete with {action_http_head_request 'test' size=0, mutating=false}; https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] amazonaws.request: Sending Request: HEAD https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: signsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsign 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: Request: HEAD https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWSCredentials: com.amazonaws.auth.BasicAWSCredentials@3391763d 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: super.getServiceName: s3-outposts 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 Canonical Request: '"HEAD /test amz-sdk-invocation-id:a467224e-06d4-2401-ef09-56998c3e9b7d amz-sdk-request:ttl=20230509T122550Z;attempt=1;max=21 amz-sdk-retry:0/0/500 content-type:application/octet-stream host:ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com referer:https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 user-agent:Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy x-amz-content-sha256:UNSIGNED-PAYLOAD x-amz-date:20230509T122230Z amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date UNSIGNED-PAYLOAD" 2023-05-09T12:22:30,285 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230509T122230Z 20230509/ap-northeast-1/s3-outposts/aws4_request b4b9e67cf72af0e4a9796a988c5991e7c22c7d43f82f20927d3409d0efb9c1c8" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] protocol.RequestAddCookies: CookieSpec selected: default 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] protocol.RequestAuthCache: Auth cache not set in the context 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection leased: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] execchain.MainClientExec: Executing request HEAD /test HTTP/1.1 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] execchain.MainClientExec: Proxy auth state: UNCHALLENGED 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> HEAD /test HTTP/1.1 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-invocation-id: a467224e-06d4-2401-ef09-56998c3e9b7d 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-retry: 0/0/500 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=1ecf8c91263647383ea51acb6d1d001595623be666e6eba8a89c76c359484a77 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Type: application/octet-stream 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> x-amz-content-sha256: UNSIGNED-PAYLOAD 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> X-Amz-Date: 20230509T122230Z 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Connection: Keep-Alive 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "HEAD /test HTTP/1.1[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-invocation-id: a467224e-06d4-2401-ef09-56998c3e9b7d[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-retry: 0/0/500[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=1ecf8c91263647383ea51acb6d1d001595623be666e6eba8a89c76c359484a77[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Type: application/octet-stream[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "x-amz-content-sha256: UNSIGNED-PAYLOAD[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "X-Amz-Date: 20230509T122230Z[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 2023-05-09T12:22:30,286 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "HTTP/1.1 404 Not Found[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Type: application/xml[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Server: AmazonS3[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-id-2: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-request-id: 1C3D6D2348D9B0F1[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Date: Tue, 09 May 2023 12:22:30 GMT[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "[\r][\n]" 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << HTTP/1.1 404 Not Found 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Type: application/xml 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Server: AmazonS3 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-id-2: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-request-id: 1C3D6D2348D9B0F1 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Date: Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] execchain.MainClientExec: Connection can be kept alive for 60000 MILLISECONDS 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443] can be kept alive for 60.0 seconds 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 0 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection released: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,345 DEBUG [pool-6-thread-199] retry.ClockSkewAdjuster: Reported server date (from 'Date' header): Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,346 DEBUG [pool-6-thread-199] amazonaws.request: Received error response: com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 1C3D6D2348D9B0F1; S3 Extended Request ID: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1; Proxy: null), S3 Extended Request ID: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1 2023-05-09T12:22:30,346 DEBUG [pool-6-thread-199] amazonaws.latency: ServiceName=[Amazon S3], AWSErrorCode=[404 Not Found], StatusCode=[404], ServiceEndpoint=[https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com], Exception=[com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: Amazon S3; Status Code: 404; Error Code: 404 Not Found; Request ID: 1C3D6D2348D9B0F1; S3 Extended Request ID: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1; Proxy: null), S3 Extended Request ID: IwjDDt9SJSmNe+ursV3Yu6yZH0ffN1m290i5PhnM9Ry/0XCQUkQu50vUf9SKwpzmvPlK/s45TEYKLQLDDL999261h4qz24B1], RequestType=[GetObjectMetadataRequest], AWSRequestID=[1C3D6D2348D9B0F1], HttpClientPoolPendingCount=0, RetryCapacityConsumed=0, HttpClientPoolAvailableCount=1, RequestCount=1, Exception=1, HttpClientPoolLeasedCount=0, ClientExecuteTime=[61.212], HttpClientSendRequestTime=[0.617], HttpRequestTime=[59.936], ApiCallLatency=[60.826], RequestSigningTime=[0.354], CredentialsRequestTime=[0.006, 0.005], HttpClientReceiveResponseTime=[58.622], 2023-05-09T12:22:30,346 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: LIST List ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3:/test/ delimiter=/ keys=2 requester pays=false 2023-05-09T12:22:30,346 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Starting: LIST 2023-05-09T12:22:30,346 DEBUG [pool-6-thread-199] impl.LoggingAuditor: [228] 7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016 Executing op_delete with {object_list_request 'test/' size=2, mutating=false}; https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] amazonaws.request: Sending Request: GET https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com / 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: signsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsign 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: Request: GET https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com / 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWSCredentials: com.amazonaws.auth.BasicAWSCredentials@38a54f3e 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: super.getServiceName: s3-outposts 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 Canonical Request: '"GET / delimiter=%2F&fetch-owner=false&list-type=2&max-keys=2&prefix=test%2F amz-sdk-invocation-id:ab9a4ce1-c1ea-c162-5f61-53d93d6634eb amz-sdk-request:ttl=20230509T122550Z;attempt=1;max=21 amz-sdk-retry:0/0/500 content-type:application/octet-stream host:ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com referer:https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 user-agent:Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy x-amz-content-sha256:UNSIGNED-PAYLOAD x-amz-date:20230509T122230Z amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date UNSIGNED-PAYLOAD" 2023-05-09T12:22:30,347 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230509T122230Z 20230509/ap-northeast-1/s3-outposts/aws4_request 6320385ce8317c4a768e4bf7a39da147641b26e1ba0ee6f1227de0bef9143bba" 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] protocol.RequestAddCookies: CookieSpec selected: default 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] protocol.RequestAuthCache: Auth cache not set in the context 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection leased: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] execchain.MainClientExec: Executing request GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] execchain.MainClientExec: Proxy auth state: UNCHALLENGED 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-invocation-id: ab9a4ce1-c1ea-c162-5f61-53d93d6634eb 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-retry: 0/0/500 2023-05-09T12:22:30,348 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=e8235a42c390515505d65c40f02d4666bbb174d19af86663a93fee72d0abedab 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Type: application/octet-stream 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> x-amz-content-sha256: UNSIGNED-PAYLOAD 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> X-Amz-Date: 20230509T122230Z 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Length: 0 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Connection: Keep-Alive 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "GET /?list-type=2&delimiter=%2F&max-keys=2&prefix=test%2F&fetch-owner=false HTTP/1.1[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-invocation-id: ab9a4ce1-c1ea-c162-5f61-53d93d6634eb[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-retry: 0/0/500[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=e8235a42c390515505d65c40f02d4666bbb174d19af86663a93fee72d0abedab[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Type: application/octet-stream[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "x-amz-content-sha256: UNSIGNED-PAYLOAD[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "X-Amz-Date: 20230509T122230Z[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Length: 0[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 2023-05-09T12:22:30,349 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "HTTP/1.1 200 OK[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Type: application/xml[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Server: AmazonS3[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-bucket-region: ap-northeast-1[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-id-2: 3YB0eJtfn9mXnHH3XwvJm4+bVYQDz+LZDpSUFpuShSZo84aB8YXwaKW1vKAw77kP4uGNPfZqsBw/dwe1fep9pAqaelO8K1ui[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-request-id: 1FF39528DC230CAC[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Date: Tue, 09 May 2023 12:22:30 GMT[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Content-Length: 442[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "[\r][\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "<?xml version="1.0" encoding="UTF-8"?>[\n]" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "<ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Contents><ETag>&quot;d41d8cd98f00b204e9800998ecf8427e&quot;</ETag><Key>test/</Key><LastModified>2023-05-09T10:37:06.472Z</LastModified><Size>0</Size><StorageClass>OUTPOSTS</StorageClass></Contents><Delimiter>/</Delimiter><IsTruncated>false</IsTruncated><KeyCount>1</KeyCount><MaxKeys>2</MaxKeys><Prefix>test/</Prefix></ListBucketResult>" 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << HTTP/1.1 200 OK 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Type: application/xml 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Server: AmazonS3 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-bucket-region: ap-northeast-1 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-id-2: 3YB0eJtfn9mXnHH3XwvJm4+bVYQDz+LZDpSUFpuShSZo84aB8YXwaKW1vKAw77kP4uGNPfZqsBw/dwe1fep9pAqaelO8K1ui 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-request-id: 1FF39528DC230CAC 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Date: Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Content-Length: 442 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] execchain.MainClientExec: Connection can be kept alive for 60000 MILLISECONDS 2023-05-09T12:22:30,408 DEBUG [pool-6-thread-199] retry.ClockSkewAdjuster: Reported server date (from 'Date' header): Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] transform.XmlResponsesSaxParser: Sanitizing XML document destined for handler class com.amazonaws.services.s3.model.transform.XmlResponsesSaxParser$ListObjectsV2Handler 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443] can be kept alive for 60.0 seconds 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 0 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection released: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] transform.XmlResponsesSaxParser: Parsing XML response document with handler: class com.amazonaws.services.s3.model.transform.XmlResponsesSaxParser$ListObjectsV2Handler 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] amazonaws.request: Received successful response: 200, AWS Request ID: 1FF39528DC230CAC 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] amazonaws.requestId: x-amzn-RequestId: not available 2023-05-09T12:22:30,410 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Request ID: 1FF39528DC230CAC 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Extended Request ID: 3YB0eJtfn9mXnHH3XwvJm4+bVYQDz+LZDpSUFpuShSZo84aB8YXwaKW1vKAw77kP4uGNPfZqsBw/dwe1fep9pAqaelO8K1ui 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] amazonaws.latency: ServiceName=[Amazon S3], StatusCode=[200], ServiceEndpoint=[https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com], RequestType=[ListObjectsV2Request], AWSRequestID=[1FF39528DC230CAC], HttpClientPoolPendingCount=0, RetryCapacityConsumed=0, HttpClientPoolAvailableCount=1, RequestCount=1, HttpClientPoolLeasedCount=0, ResponseProcessingTime=[1.954], ClientExecuteTime=[64.235], HttpClientSendRequestTime=[0.361], HttpRequestTime=[61.164], ApiCallLatency=[63.972], RequestSigningTime=[0.429], CredentialsRequestTime=[0.005, 0.005], HttpClientReceiveResponseTime=[59.618], 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: LIST: duration 0:00.065s 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Found path as directory (with /) 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Prefix count = 0; object count=1 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Summary: test/ 0 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.DeleteOperation: Delete path s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test - recursive true 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.DeleteOperation: Type = Empty Directory 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.DeleteOperation: delete: Path is a directory: s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.DeleteOperation: deleting empty directory s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.DeleteOperation: delete: dir marker test/ 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.Invoker: Starting: delete 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: Starting: deleting test/ 2023-05-09T12:22:30,411 DEBUG [pool-6-thread-199] impl.LoggingAuditor: [228] 7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016 Executing op_delete with {object_delete_request 'test/' size=1, mutating=true}; https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] amazonaws.request: Sending Request: DELETE https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test/ 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: signsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsignsign 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: Request: DELETE https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com /test/ 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWSCredentials: com.amazonaws.auth.BasicAWSCredentials@6ac2cf9d 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: super.getServiceName: s3-outposts 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 Canonical Request: '"DELETE /test/ amz-sdk-invocation-id:5590147b-c6c2-4cea-9b23-c23d2d39ff1d amz-sdk-request:ttl=20230509T122550Z;attempt=1;max=21 amz-sdk-retry:0/0/500 content-type:application/octet-stream host:ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com referer:https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 user-agent:Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy x-amz-content-sha256:UNSIGNED-PAYLOAD x-amz-date:20230509T122230Z amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date UNSIGNED-PAYLOAD" 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] auth.AWS4Signer: AWS4 String to Sign: '"AWS4-HMAC-SHA256 20230509T122230Z 20230509/ap-northeast-1/s3-outposts/aws4_request eb86d75dbfeaacfd17eaa86fb298491b28d76f082340eea606929f4e1046c59d" 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] protocol.RequestAddCookies: CookieSpec selected: default 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] protocol.RequestAuthCache: Auth cache not set in the context 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection leased: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 0; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 200000 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] execchain.MainClientExec: Executing request DELETE /test/ HTTP/1.1 2023-05-09T12:22:30,412 DEBUG [pool-6-thread-199] execchain.MainClientExec: Proxy auth state: UNCHALLENGED 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> DELETE /test/ HTTP/1.1 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-invocation-id: 5590147b-c6c2-4cea-9b23-c23d2d39ff1d 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> amz-sdk-retry: 0/0/500 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=1e510b053e251aa3d0433853a6bc11fb58d8478f9ab83d32f2d818504ce79db1 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Content-Type: application/octet-stream 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> x-amz-content-sha256: UNSIGNED-PAYLOAD 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> X-Amz-Date: 20230509T122230Z 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 >> Connection: Keep-Alive 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "DELETE /test/ HTTP/1.1[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Host: ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-invocation-id: 5590147b-c6c2-4cea-9b23-c23d2d39ff1d[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-request: ttl=20230509T122550Z;attempt=1;max=21[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "amz-sdk-retry: 0/0/500[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Authorization: AWS4-HMAC-SHA256 Credential=AKIAYR27EH6MARMG5SZK/20230509/ap-northeast-1/s3-outposts/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;amz-sdk-retry;content-type;host;referer;user-agent;x-amz-content-sha256;x-amz-date, Signature=1e510b053e251aa3d0433853a6bc11fb58d8478f9ab83d32f2d818504ce79db1[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Content-Type: application/octet-stream[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Referer: https://audit.example.org/hadoop/1/op_delete/7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016/?op=op_delete&p1=s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test&pr=root&ps=3d57fe75-fbbb-4fbe-88d7-b3da82481c8f&id=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa-00000016&t0=228&fs=7a75a7f2-94c9-4256-9ceb-67af2b7b26aa&t1=228&ts=1683634950284[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "User-Agent: Hadoop 3.3.5, aws-sdk-java/1.12.462 Linux/5.10.178-162.673.amzn2.x86_64 OpenJDK_64-Bit_Server_VM/11.0.19+7 java/11.0.19 kotlin/1.4.10 vendor/Eclipse_Adoptium cfg/retry-mode/legacy[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "x-amz-content-sha256: UNSIGNED-PAYLOAD[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "X-Amz-Date: 20230509T122230Z[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 2023-05-09T12:22:30,413 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 >> "[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "HTTP/1.1 204 No Content[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Server: AmazonS3[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-id-2: h8n84buCFbPodH0JVHBXLrIAZ0Bg6vyJHcIcXwM1x1ONGvepwWRakXHw50DV2Pe+WgH0SgjeowXwRirEuG7gFgba8OkYkio/[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "x-amz-request-id: F9DB90125EB634DB[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "Date: Tue, 09 May 2023 12:22:30 GMT[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.wire: http-outgoing-4 << "[\r][\n]" 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << HTTP/1.1 204 No Content 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Server: AmazonS3 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-id-2: h8n84buCFbPodH0JVHBXLrIAZ0Bg6vyJHcIcXwM1x1ONGvepwWRakXHw50DV2Pe+WgH0SgjeowXwRirEuG7gFgba8OkYkio/ 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << x-amz-request-id: F9DB90125EB634DB 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] http.headers: http-outgoing-4 << Date: Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] execchain.MainClientExec: Connection can be kept alive for 60000 MILLISECONDS 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443] can be kept alive for 60.0 seconds 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] conn.DefaultManagedHttpClientConnection: http-outgoing-4: set socket timeout to 0 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] conn.PoolingHttpClientConnectionManager: Connection released: [id: 4][route: {s}->https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com:443][total available: 1; route allocated: 1 of 96; total allocated: 1 of 96] 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] retry.ClockSkewAdjuster: Reported server date (from 'Date' header): Tue, 09 May 2023 12:22:30 GMT 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] amazonaws.request: Received successful response: 204, AWS Request ID: F9DB90125EB634DB 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] amazonaws.requestId: x-amzn-RequestId: not available 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Request ID: F9DB90125EB634DB 2023-05-09T12:22:30,470 DEBUG [pool-6-thread-199] amazonaws.requestId: AWS Extended Request ID: h8n84buCFbPodH0JVHBXLrIAZ0Bg6vyJHcIcXwM1x1ONGvepwWRakXHw50DV2Pe+WgH0SgjeowXwRirEuG7gFgba8OkYkio/ 2023-05-09T12:22:30,471 DEBUG [pool-6-thread-199] amazonaws.latency: ServiceName=[Amazon S3], StatusCode=[204], ServiceEndpoint=[https://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3.op-01427051a3dc18b69.s3-outposts.ap-northeast-1.amazonaws.com], RequestType=[DeleteObjectRequest], AWSRequestID=[F9DB90125EB634DB], HttpClientPoolPendingCount=0, RetryCapacityConsumed=0, HttpClientPoolAvailableCount=1, RequestCount=1, HttpClientPoolLeasedCount=0, ResponseProcessingTime=[0.065], ClientExecuteTime=[59.142], HttpClientSendRequestTime=[0.565], HttpRequestTime=[58.065], ApiCallLatency=[58.925], RequestSigningTime=[0.4], CredentialsRequestTime=[0.004, 0.003], HttpClientReceiveResponseTime=[56.949], 2023-05-09T12:22:30,471 DEBUG [pool-6-thread-199] s3a.S3AFileSystem: deleting test/: duration 0:00.060s 2023-05-09T12:22:30,471 DEBUG [pool-6-thread-199] s3a.Invoker: delete: duration 0:00.060s 2023-05-09T12:22:30,471 DEBUG [pool-6-thread-199] impl.DeleteOperation: Deleted 1 objects 2023-05-09T12:22:30,472 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from TXN_COMPONENTS where tc_database='test'> 2023-05-09T12:22:30,473 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from COMPLETED_TXN_COMPONENTS where ctc_database='test'> 2023-05-09T12:22:30,473 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from COMPACTION_QUEUE where cq_database='test'> 2023-05-09T12:22:30,473 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from COMPLETED_COMPACTIONS where cc_database='test'> 2023-05-09T12:22:30,474 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from TXN_TO_WRITE_ID where t2w_database='test'> 2023-05-09T12:22:30,474 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to execute update <delete from NEXT_WRITE_ID where nwi_database='test'> 2023-05-09T12:22:30,474 DEBUG [pool-6-thread-199] txn.TxnHandler: Going to commit 2023-05-09T12:22:30,474 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1038d57 2023-05-09T12:22:30,474 DEBUG [pool-6-thread-199] metrics.PerfLogger: </PERFLOG method=drop_database start=1683634949830 end=1683634950474 duration=644 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=197 retryCount=0 error=false> 2023-05-09T12:22:30,475 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Cleaning up thread local RawStore... 2023-05-09T12:22:30,475 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=Cleaning up thread local RawStore... 2023-05-09T12:22:30,475 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@1dbd1743, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@6f400b5c will be shutdown 2023-05-09T12:22:30,475 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Done cleaning up thread local RawStore 2023-05-09T12:22:30,475 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=Done cleaning up thread local RawStore 2023-05-09T12:22:31,790 DEBUG [pool-6-thread-199] metrics.PerfLogger: <PERFLOG method=get_all_databases from=org.apache.hadoop.hive.metastore.RetryingHMSHandler> 2023-05-09T12:22:31,790 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: source:10.0.201.203 get_databases: @hive# 2023-05-09T12:22:31,790 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=source:10.0.201.203 get_databases: @hive# 2023-05-09T12:22:31,791 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore 2023-05-09T12:22:31,791 WARN [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode is set to unsupported value null . Setting it to value: ignored 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.autoCreateAll value null from jpox.properties with false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionDriverName value null from jpox.properties with org.postgresql.Driver 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPool.maxPoolSize value null from jpox.properties with 10 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPoolingType value null from jpox.properties with HikariCP 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionURL value null from jpox.properties with jdbc:postgresql://lighthouse-outpost-dev-hivemetastoredb.cm25znb924dp.ap-northeast-1.rds.amazonaws.com:5432/hivemetastoredb?allowPublicKeyRetrieval=true&useSSL=false&serverTimezone=UTC 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionUserName value null from jpox.properties with postgres 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.autoStartMechanismMode value null from jpox.properties with ignored 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2 value null from jpox.properties with false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2.type value null from jpox.properties with none 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.initializeColumnInfo value null from jpox.properties with NONE 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.plugin.pluginRegistryBundleCheck value null from jpox.properties with LOG 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.transactionIsolation value null from jpox.properties with read-committed 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.useLegacyNativeValueStrategy value null from jpox.properties with true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.DetachAllOnCommit value null from jpox.properties with true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.identifierFactory value null from jpox.properties with datanucleus1 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.PersistenceManagerFactoryClass value null from jpox.properties with org.datanucleus.api.jdo.JDOPersistenceManagerFactory 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.Multithreaded value null from jpox.properties with true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.NonTransactionalRead value null from jpox.properties with true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.storeManagerType value null from jpox.properties with rdbms 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateColumns value null from jpox.properties with false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateConstraints value null from jpox.properties with false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateTables value null from jpox.properties with false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.useLegacyNativeValueStrategy = true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateConstraints = false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionUserName = postgres 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.storeManagerType = rdbms 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionDriverName = org.postgresql.Driver 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2.type = none 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.NonTransactionalRead = true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionURL = jdbc:postgresql://lighthouse-outpost-dev-hivemetastoredb.cm25znb924dp.ap-northeast-1.rds.amazonaws.com:5432/hivemetastoredb?allowPublicKeyRetrieval=true&useSSL=false&serverTimezone=UTC 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPool.maxPoolSize = 10 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.initializeColumnInfo = NONE 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPoolingType = HikariCP 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateColumns = false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.transactionIsolation = read-committed 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2 = false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.autoCreateAll = false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.identifierFactory = datanucleus1 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.Multithreaded = true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.plugin.pluginRegistryBundleCheck = LOG 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.PersistenceManagerFactoryClass = org.datanucleus.api.jdo.JDOPersistenceManagerFactory 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.DetachAllOnCommit = true 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateTables = false 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode = ignored 2023-05-09T12:22:31,791 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@48f52747, with PersistenceManager: null will be shutdown 2023-05-09T12:22:31,791 INFO [pool-6-thread-199] metastore.ObjectStore: ObjectStore, initialize called 2023-05-09T12:22:31,794 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@512f3c4c 2023-05-09T12:22:31,795 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@512f3c4c 2023-05-09T12:22:31,798 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-2 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@512f3c4c 2023-05-09T12:22:31,800 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@7ce3e4dc 2023-05-09T12:22:31,800 INFO [pool-6-thread-199] metastore.MetaStoreDirectSql: Using direct SQL, underlying DB is POSTGRES 2023-05-09T12:22:31,800 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@48f52747, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@2d2e05df created in the thread with id: 228 2023-05-09T12:22:31,800 INFO [pool-6-thread-199] metastore.ObjectStore: Initialized ObjectStore 2023-05-09T12:22:31,800 DEBUG [pool-6-thread-199] metastore.ObjectStore: Open transaction: count = 1, isActive = true at: org.apache.hadoop.hive.metastore.ObjectStore.getAllDatabases(ObjectStore.java:1151) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) 2023-05-09T12:22:31,802 DEBUG [pool-6-thread-199] metastore.ObjectStore: Commit transaction: count = 0, isactive true at: org.apache.hadoop.hive.metastore.ObjectStore.getAllDatabases(ObjectStore.java:1158) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) 2023-05-09T12:22:31,802 DEBUG [pool-6-thread-199] pool.PoolBase: HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@7ce3e4dc 2023-05-09T12:22:31,802 DEBUG [pool-6-thread-199] metrics.PerfLogger: </PERFLOG method=get_all_databases start=1683634951790 end=1683634951802 duration=12 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=197 retryCount=0 error=false> 2023-05-09T12:22:31,802 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Cleaning up thread local RawStore... 2023-05-09T12:22:31,802 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=Cleaning up thread local RawStore... 2023-05-09T12:22:31,802 DEBUG [pool-6-thread-199] metastore.ObjectStore: RawStore: org.apache.hadoop.hive.metastore.ObjectStore@48f52747, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@2d2e05df will be shutdown 2023-05-09T12:22:31,802 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Done cleaning up thread local RawStore 2023-05-09T12:22:31,802 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=Done cleaning up thread local RawStore 2023-05-09T12:22:31,804 DEBUG [pool-6-thread-199] metrics.PerfLogger: <PERFLOG method=create_database from=org.apache.hadoop.hive.metastore.RetryingHMSHandler> 2023-05-09T12:22:31,804 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: source:10.0.201.203 create_database: Database(name:test, description:null, locationUri:s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test, parameters:{presto_query_id=20230509_122231_00012_tcfvh}, ownerName:trino, ownerType:USER) 2023-05-09T12:22:31,804 INFO [pool-6-thread-199] HiveMetaStore.audit: ugi=root ip=10.0.201.203 cmd=source:10.0.201.203 create_database: Database(name:test, description:null, locationUri:s3a://ipass-datala-o01427051a3dc18b69nmaa8betpfvhubhf2siqapn10--op-s3/test, parameters:{presto_query_id=20230509_122231_00012_tcfvh}, ownerName:trino, ownerType:USER) 2023-05-09T12:22:31,805 INFO [pool-6-thread-199] metastore.HiveMetaStore: 197: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore 2023-05-09T12:22:31,805 WARN [pool-6-thread-199] metastore.ObjectStore: datanucleus.autoStartMechanismMode is set to unsupported value null . Setting it to value: ignored 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.autoCreateAll value null from jpox.properties with false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionDriverName value null from jpox.properties with org.postgresql.Driver 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPool.maxPoolSize value null from jpox.properties with 10 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.connectionPoolingType value null from jpox.properties with HikariCP 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionURL value null from jpox.properties with jdbc:postgresql://lighthouse-outpost-dev-hivemetastoredb.cm25znb924dp.ap-northeast-1.rds.amazonaws.com:5432/hivemetastoredb?allowPublicKeyRetrieval=true&useSSL=false&serverTimezone=UTC 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.ConnectionUserName value null from jpox.properties with postgres 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.autoStartMechanismMode value null from jpox.properties with ignored 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2 value null from jpox.properties with false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.cache.level2.type value null from jpox.properties with none 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.initializeColumnInfo value null from jpox.properties with NONE 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.plugin.pluginRegistryBundleCheck value null from jpox.properties with LOG 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.transactionIsolation value null from jpox.properties with read-committed 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.rdbms.useLegacyNativeValueStrategy value null from jpox.properties with true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.DetachAllOnCommit value null from jpox.properties with true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.identifierFactory value null from jpox.properties with datanucleus1 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.PersistenceManagerFactoryClass value null from jpox.properties with org.datanucleus.api.jdo.JDOPersistenceManagerFactory 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.Multithreaded value null from jpox.properties with true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding javax.jdo.option.NonTransactionalRead value null from jpox.properties with true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.storeManagerType value null from jpox.properties with rdbms 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateColumns value null from jpox.properties with false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateConstraints value null from jpox.properties with false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: Overriding datanucleus.schema.validateTables value null from jpox.properties with false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.useLegacyNativeValueStrategy = true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateConstraints = false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionUserName = postgres 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.storeManagerType = rdbms 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionDriverName = org.postgresql.Driver 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2.type = none 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.NonTransactionalRead = true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.ConnectionURL = jdbc:postgresql://lighthouse-outpost-dev-hivemetastoredb.cm25znb924dp.ap-northeast-1.rds.amazonaws.com:5432/hivemetastoredb?allowPublicKeyRetrieval=true&useSSL=false&serverTimezone=UTC 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPool.maxPoolSize = 10 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.rdbms.initializeColumnInfo = NONE 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.connectionPoolingType = HikariCP 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.validateColumns = false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.transactionIsolation = read-committed 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.cache.level2 = false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.schema.autoCreateAll = false 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: datanucleus.identifierFactory = datanucleus1 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: javax.jdo.option.Multithreaded = true 2023-05-09T12:22:31,805 DEBUG [pool-6-thread-199] metastore.ObjectStore: ```