Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore(executor): print exception stacktrace in executor #3205

Merged
merged 1 commit into from
Jul 9, 2024

Conversation

harshachinta
Copy link
Contributor

@harshachinta harshachinta commented Jul 9, 2024

In some scenarios during systest execution the error description is getting masked and is shown as null. This makes debugging the error harder. Adding an additional log to print the exception along with stack trace.
b/350177934

Example:
The below logging happens at this place https://github.com/googleapis/java-spanner/blob/main/google-cloud-spanner-executor/src/main/java/com/google/cloud/executor/spanner/CloudClientExecutor.java#L2669-L2673.


 2024-06-29 06:10:52.179275-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudClientExecutor executeQuery
 2024-06-29 06:10:52.179291-07007   INFO: Executing query Writes2-auto-1719665201034008-429/4011
 2024-06-29 06:10:52.179298-07007   sql: "@{ spanner.require_enhance_query = true }\nSELECT\n  orderbyscan_67.a_4 AS col59,\n  orderbyscan_67.a_1 AS col57,\n  orderbyscan_67.a_62 AS col116,\n  orderbyscan_67.a_48 AS col102,\n  CAST(NULL AS BOOL) AS col119,\n  orderbyscan_67.a_63 AS col120\nFROM\n  (\n    SELECT\n      filterscan_66.a_1 AS a_1,\n      filterscan_66.a_4 AS a_4,\n      filterscan_66.a_48 AS a_48,\n      filterscan_66.a_62 AS a_62,\n      filterscan_66.a_63 AS a_63\n    FROM\n      (\n        SELECT\n          projectscan_5.a_1 AS a_1,\n          projectscan_5.a_4 AS a_4,\n          projectscan_64.a_48 AS a_48,\n          projectscan_64.a_62 AS a_62,\n          projectscan_64.a_63 AS a_63\n        FROM\n          (\n            SELECT\n              orderbyscan_3.a_1 AS a_1,\n              CAST(@p0 AS INT64) AS a_4\n            FROM\n              (\n                SELECT\n                  filterscan_2.a_1 AS a_1\n                FROM\n                  (\n                    SELECT\n                      SqlSearchSingers.SingerId AS a_1\n                    FROM\n                      SqlSearchSingers\n                    WHERE\n                      (SqlSearchSingers.SingerId) = 78\n                  ) AS filterscan_2\n                ORDER BY filterscan_2.a_1 DESC, filterscan_2.a_1 DESC\n              ) AS orderbyscan_3\n          ) AS projectscan_5\n          INNER JOIN\n          @{ spanner.join_method = \"loop_join\" }\n          (\n            SELECT\n              SqlSearchAlbums.Rating AS a_48,\n              SCORE_NGRAMS(SqlSearchAlbums.Tracks_Substring_Tokens, \"kOn4TcygPawzuArqyvONrxohAGBKoFupxii4Z\\nmDHnJwPS\") AS a_62,\n              DEBUG_TOKENLIST(SqlSearchAlbums.Rating_Tokens) AS a_63\n            FROM\n              SqlSearchAlbums @{ force_index = \"SqlSearchAlbumsNoDivSearchIndex\" }\n            WHERE\n              (((((((SqlSearchAlbums.AlternativeName) IN (b\"text full full full \", b\"FLqJgAwP\", b\"GdgBY2dlyiTHIxYH5C7vl3vKZqW4y\")) AND\n              ((SEARCH_SUBSTRING(SqlSearchAlbums.Tracks_Substring_Tokens, \"awzuArqyvONrxohAGBKoFu\")) OR (SEARCH_NGRAMS(SqlSearchAlbums.Tracks_Substring_Tokens,\n                \"kOn4TcygPawzuArqyvONrxohAGBKoFupxii4Z\\nmDHnJwPS\")))) AND ((SqlSearchAlbums.Rating) >= CAST(NULL AS FLOAT64))) AND\n              (SEARCH(SqlSearchAlbums.Text_Tokens, \'\"Spanner AROUND(8) Spanner search\"\', enhance_query  => true))) AND\n              (CAST(NULL AS INT64) <= (SqlSearchAlbums.Length))) AND (7537955017849946775 > (SqlSearchAlbums.Profit))) AND\n              ((SqlSearchAlbums.SingerId) = 78)\n          ) AS projectscan_64\n          ON (\n              SELECT\n                SAFE_CAST(JSON_VALUE(\'{\"array\":[null,1.3589607628108293e+308],\"bool\":false,\"null\":null,\"number_float\":1.7010656682977979e+308,\"number_integer\":2989478548941050409,\"number_unsigned\":14203771396237232853,\"object\":{\"array\":[-261631567938255465],\"string\":\"TiUFnQoWz9K5l8\"},\"string\":\"DeRGvNTSbmkwYf35mbCTq8mI54WfOiK0eu2whtJ:0hKd5IauIK:C3PlX6RTdRDg\"}\',\n                  \"$.bool\") AS BOOL) AS a_65\n              LIMIT 1 OFFSET 0)\n        WHERE\n          (projectscan_64.a_63) IN (\"tWkBDt1KlB:MWpk6Y9KQ67EHz:ULdJtcf2w\", CAST(NULL AS STRING))\n      ) AS filterscan_66\n    ORDER BY filterscan_66.a_4\n  ) AS orderbyscan_67;"
 2024-06-29 06:10:52.179306-07007   params {
 2024-06-29 06:10:52.179307-07007     name: "p0"
 2024-06-29 06:10:52.179312-07007     type {
 2024-06-29 06:10:52.179313-07007       code: STRING
 2024-06-29 06:10:52.179314-07007     }
 2024-06-29 06:10:52.179316-07007     value {
 2024-06-29 06:10:52.179317-07007       string_value: "K7tCW382wr0aysd2FhkYpMWl"
 2024-06-29 06:10:52.179318-07007     }
 2024-06-29 06:10:52.179319-07007   }
 2024-06-29 06:10:52.179320-07007   
 2024-06-29 06:10:52.179321-07007   
 2024-06-29 06:10:52.179365-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudClientExecutor executeQuery
 2024-06-29 06:10:52.179367-07007   INFO: Finish query building, ready to execute Writes2-auto-1719665201034008-429/4011
 2024-06-29 06:10:52.179416-07007   
 2024-06-29 06:10:52.180071-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudClientExecutor executeQuery
 2024-06-29 06:10:52.180083-07007   INFO: Parsing query result Writes2-auto-1719665201034008-429/4011
 2024-06-29 06:10:52.180086-07007   
 2024-06-29 06:10:52.180452-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudClientExecutor processResults
 2024-06-29 06:10:52.180460-07007   INFO: Iterating result set: Writes2-auto-1719665201034008-429/4011
 2024-06-29 06:10:52.180463-07007   
 2024-06-29 06:10:52.235759-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudClientExecutor processResults
 2024-06-29 06:10:52.235785-07007   WARNING: Encountered exception: : null Writes2-auto-1719665201034008-429/4011
 2024-06-29 06:10:52.235789-07007   
 2024-06-29 06:10:52.236111-07007   Jun 29, 2024 6:10:52 AM com.google.cloud.executor.spanner.CloudExecutor$OutcomeSender sendOutcome
 2024-06-29 06:10:52.236123-07007   INFO: Sending result status {
 2024-06-29 06:10:52.236126-07007     code: 13
 2024-06-29 06:10:52.236127-07007     message: ": null"

@harshachinta harshachinta requested a review from a team as a code owner July 9, 2024 10:56
@product-auto-label product-auto-label bot added size: xs Pull request size is extra small. api: spanner Issues related to the googleapis/java-spanner API. labels Jul 9, 2024
@harshachinta harshachinta changed the title chore(spanner): add extra logging in executor chore(executor): add extra logging in executor Jul 9, 2024
@harshachinta harshachinta changed the title chore(executor): add extra logging in executor chore(executor): print exception stacktrace in executor Jul 9, 2024
@harshachinta harshachinta merged commit 1fb54b9 into googleapis:main Jul 9, 2024
31 of 32 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: spanner Issues related to the googleapis/java-spanner API. size: xs Pull request size is extra small.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants