From 1d7592df58e73503cf9dd093afffa522f307c461 Mon Sep 17 00:00:00 2001 From: Cameron Dawson Date: Sun, 5 Jul 2026 07:46:17 -0700 Subject: [PATCH] Add GCP structured log labels for task_id/run_id on backend logs Attach task_id, run_id, job_id and component as queryable GCP Cloud Logging labels to backend log lines, so CI failures can be investigated per Taskcluster task/run rather than only per prototype/stage. Today most lines are plaintext with, at best, an internal job_id interpolated into the message string; task_id is not queryable. - treeherder/utils/logging_context.py: contextvars-based log_context() context manager/decorator, get_log_labels(), a job_log_labels() resolver (task_id/run_id from TaskclusterMetadata) and the apply_context_labels() helper. No third-party imports. - treeherder/utils/gcp_logging.py: ContextLabelStructuredLogHandler, a StructuredLogHandler subclass that stamps context labels onto each record before the handler's filter phase. google-cloud-logging's built-in CloudLoggingFilter reads record.labels, so a filter added after it (the usual pattern) is too late and the labels are dropped. - config/settings.py: GCP_STRUCTURED_LOGGING env flag (default off) routes the treeherder logger through the structured handler. Off by default so local/dev keeps human-readable plaintext. - log_parser/tasks.py and etl/taskcluster_pulse/handler.py: wrap the log-parsing and pulse-ingestion entry points in log_context so every related line -- including deeper failure-line processing -- inherits the labels without editing individual log calls. - requirements: add google-cloud-logging (structured stdout mode; no GCP credentials or API calls). --- requirements/common.in | 3 + requirements/common.txt | 178 ++++++++++---------- tests/etl/taskcluster_pulse/test_handler.py | 41 +++++ tests/utils/test_gcp_logging.py | 51 ++++++ tests/utils/test_logging_context.py | 108 ++++++++++++ treeherder/config/settings.py | 15 ++ treeherder/etl/taskcluster_pulse/handler.py | 75 +++++---- treeherder/log_parser/tasks.py | 105 ++++++------ treeherder/utils/gcp_logging.py | 25 +++ treeherder/utils/logging_context.py | 66 ++++++++ 10 files changed, 496 insertions(+), 171 deletions(-) create mode 100644 tests/utils/test_gcp_logging.py create mode 100644 tests/utils/test_logging_context.py create mode 100644 treeherder/utils/gcp_logging.py create mode 100644 treeherder/utils/logging_context.py diff --git a/requirements/common.in b/requirements/common.in index f09e0dafa57..b025657129a 100644 --- a/requirements/common.in +++ b/requirements/common.in @@ -40,6 +40,9 @@ mozci[cache]==2.4.3 # Dockerflow/CloudOps APIs dockerflow==2026.3.4 +# Structured logging to GCP Cloud Logging (task_id/run_id labels) +google-cloud-logging==3.16.0 + # Measuring noise of perf data moz-measure-noise==2.70.0 diff --git a/requirements/common.txt b/requirements/common.txt index 80bdf479b26..af7a095b48c 100644 --- a/requirements/common.txt +++ b/requirements/common.txt @@ -1,5 +1,5 @@ # -# This file is autogenerated by pip-compile with Python 3.12 +# This file is autogenerated by pip-compile with Python 3.13 # by the following command: # # pip-compile --generate-hashes --output-file=requirements/common.txt requirements/common.in @@ -806,15 +806,27 @@ google-api-core[grpc]==2.24.1 \ --hash=sha256:bc78d608f5a5bf853b80bd70a795f703294de656c096c0968320830a4bc280f1 \ --hash=sha256:f8b36f5456ab0dd99a1b693a40a31d1e7757beea380ad1b38faaf8941eae9d8a # via + # google-cloud-appengine-logging # google-cloud-bigquery # google-cloud-core + # google-cloud-logging google-auth==2.38.0 \ --hash=sha256:8285113607d3b80a3f1543b75962447ba8a09fe85783432a784fdeef6ac094c4 \ --hash=sha256:e7dae6694313f434a2727bf2906f27ad259bae090d7aa896590d86feec3d9d4a # via # google-api-core + # google-cloud-appengine-logging # google-cloud-bigquery # google-cloud-core + # google-cloud-logging +google-cloud-appengine-logging==1.10.0 \ + --hash=sha256:193675caaf062c41688a3e2c744b73614db82408bc7fb060353b6878d7134492 \ + --hash=sha256:b5563e76010a36e6adf1cc489620c29ee4fb3b986b006d237e9a061eb0f0abb7 + # via google-cloud-logging +google-cloud-audit-log==0.6.0 \ + --hash=sha256:4dd343683c0bb31187ebef3426803f13159e950fbea3fe60a864855cfed959b8 \ + --hash=sha256:8c5ecbc341ad3b3daf776981f6d7fd7ab5ff5a29c5dce3172c669b570e0f6717 + # via google-cloud-logging google-cloud-bigquery==3.29.0 \ --hash=sha256:5453a4eabe50118254eda9778f3d7dad413490de5f7046b5e66c98f5a1580308 \ --hash=sha256:fafc2b455ffce3bcc6ce0e884184ef50b6a11350a83b91e327fadda4d5566e72 @@ -822,7 +834,13 @@ google-cloud-bigquery==3.29.0 \ google-cloud-core==2.4.1 \ --hash=sha256:9b7749272a812bde58fff28868d0c5e2f585b82f37e09a1f6ed2d4d10f134073 \ --hash=sha256:a9e6a4422b9ac5c29f79a0ede9485473338e2ce78d91f2370c01e730eab22e61 - # via google-cloud-bigquery + # via + # google-cloud-bigquery + # google-cloud-logging +google-cloud-logging==3.16.0 \ + --hash=sha256:08a3076b8f0f724219d6f73b2a242ef69d51e8bce226133aebe41a25f23f5400 \ + --hash=sha256:9e5bfbdfe7b5315ece00e1703a2ea25fe42ca35e0b4750127b019f50d069b01b + # via -r requirements/common.in google-crc32c==1.6.0 \ --hash=sha256:05e2d8c9a2f853ff116db9706b4a27350587f341eda835f46db3c0a8c8ce2f24 \ --hash=sha256:18e311c64008f1f1379158158bb3f0c8d72635b9eb4f9545f8cf990c5668e59d \ @@ -856,12 +874,18 @@ google-resumable-media==2.7.2 \ --hash=sha256:3ce7551e9fe6d99e9a126101d2536612bb73486721951e9562fee0f90c6ababa \ --hash=sha256:5280aed4629f2b60b847b0d42f9857fd4935c11af266744df33d8074cae92fe0 # via google-cloud-bigquery -googleapis-common-protos==1.67.0 \ +googleapis-common-protos[grpc]==1.67.0 \ --hash=sha256:21398025365f138be356d5923e9168737d94d46a72aefee4a6110a1f23463c86 \ --hash=sha256:579de760800d13616f51cf8be00c876f00a9f146d3e6510e19d1f4111758b741 # via # google-api-core + # google-cloud-audit-log + # grpc-google-iam-v1 # grpcio-status +grpc-google-iam-v1==0.14.4 \ + --hash=sha256:392b3796947ed6334e61171d9ab06bf7eb357f554e5fc7556ad7aab6d0e17038 \ + --hash=sha256:412facc320fcbd94034b4df3d557662051d4d8adfa86e0ddb4dca70a3f739964 + # via google-cloud-logging grpcio==1.70.0 \ --hash=sha256:0495c86a55a04a874c7627fd33e5beaee771917d92c0e6d9d797628ac40e7655 \ --hash=sha256:07269ff4940f6fb6710951116a04cd70284da86d0a4368fd5a3b552744511f5a \ @@ -920,6 +944,10 @@ grpcio==1.70.0 \ --hash=sha256:ff4a8112a79464919bb21c18e956c54add43ec9a4850e3949da54f61c241a4a6 # via # google-api-core + # google-cloud-appengine-logging + # google-cloud-logging + # googleapis-common-protos + # grpc-google-iam-v1 # grpcio-status grpcio-status==1.70.0 \ --hash=sha256:0e7b42816512433b18b9d764285ff029bde059e9d41f8fe10a60631bd8348101 \ @@ -1537,6 +1565,10 @@ numpy==2.2.6 \ # moz-measure-noise # pandas # scipy +opentelemetry-api==1.43.0 \ + --hash=sha256:107d0d03857ea8fc7c5fcbbbd83f800c281f0d560553d61c1d675fccfd1761c1 \ + --hash=sha256:20acf45e9b21851926835292e4045d290acade1edd2ff3de86d2f069687ba1fd + # via google-cloud-logging orderedmultidict==1.0.1 \ --hash=sha256:04070bbb5e87291cc9bfa51df413677faf2141c73c61d2a5f7b26bea3cd882ad \ --hash=sha256:43c839a17ee3cdd62234c47deca1a8508a3f2ca1d0678a3bf791c87cf84adbf3 @@ -1810,7 +1842,10 @@ propcache==0.3.2 \ proto-plus==1.26.0 \ --hash=sha256:6e93d5f5ca267b54300880fff156b6a3386b3fa3f43b1da62e680fc0c586ef22 \ --hash=sha256:bf2dfaa3da281fc3187d12d224c707cb57214fb2c22ba854eb0c105a3fb2d4d7 - # via google-api-core + # via + # google-api-core + # google-cloud-appengine-logging + # google-cloud-logging protobuf==5.29.3 \ --hash=sha256:0a18ed4a24198528f2333802eb075e59dea9d679ab7a6c5efb017a59004d849f \ --hash=sha256:0eb32bfa5219fc8d4111803e9a690658aa2e6366384fd0851064b963b6d1f2a7 \ @@ -1825,69 +1860,73 @@ protobuf==5.29.3 \ --hash=sha256:daaf63f70f25e8689c072cfad4334ca0ac1d1e05a92fc15c54eb9cf23c3efd84 # via # google-api-core + # google-cloud-appengine-logging + # google-cloud-audit-log + # google-cloud-logging # googleapis-common-protos + # grpc-google-iam-v1 # grpcio-status # proto-plus -psycopg==3.3.3 \ +psycopg[binary]==3.3.3 \ --hash=sha256:5e9a47458b3c1583326513b2556a2a9473a1001a56c9efe9e587245b43148dd9 \ --hash=sha256:f96525a72bcfade6584ab17e89de415ff360748c766f0106959144dcbb38c698 # via -r requirements/common.in psycopg-binary==3.3.3 \ - --hash=sha256:b3385b58b2fe408a13d084c14b8dcf468cd36cbbe774408250facc128f9fa75c \ - --hash=sha256:1bef235a50a80f6aba05147002bc354559657cb6386dbd04d8e1c97d1d7cbe84 \ - --hash=sha256:97c839717bf8c8df3f6d983a20949c4fb22e2a34ee172e3e427ede363feda27b \ - --hash=sha256:48e500cf1c0984dacf1f28ea482c3cdbb4c2288d51c336c04bc64198ab21fc51 \ - --hash=sha256:eb36a08859b9432d94ea6b26ec41a2f98f83f14868c91321d0c1e11f672eeae7 \ + --hash=sha256:05f32239aec25c5fb15f7948cffdc2dc0dac098e48b80a140e4ba32b572a2e7d \ + --hash=sha256:07c7211f9327d522c9c47560cae00a4ecf6687f4e02d779d035dd3177b41cb12 \ --hash=sha256:0dde92cfde09293fb63b3f547919ba7d73bd2654573c03502b3263dd0218e44e \ - --hash=sha256:78c9ce98caaf82ac8484d269791c1b403d7598633e0e4e2fa1097baae244e2f1 \ - --hash=sha256:d593612758d0041cb13cb0003f7f8d3fabb7ad9319e651e78afae49b1cf5860e \ - --hash=sha256:f24e8e17035200a465c178e9ea945527ad0738118694184c450f1192a452ff25 \ - --hash=sha256:e7b607f0e14f2a4cf7e78a05ebd13df6144acfba87cb90842e70d3f125d9f53f \ - --hash=sha256:b27d3a23c79fa59557d2cc63a7e8bb4c7e022c018558eda36f9d7c4e6b99a6e0 \ - --hash=sha256:a89bb9ee11177b2995d87186b1d9fa892d8ea725e85eab28c6525e4cc14ee048 \ - --hash=sha256:9f7d0cf072c6fbac3795b08c98ef9ea013f11db609659dcfc6b1f6cc31f9e181 \ - --hash=sha256:90eecd93073922f085967f3ed3a98ba8c325cbbc8c1a204e300282abd2369e13 \ - --hash=sha256:dac7ee2f88b4d7bb12837989ca354c38d400eeb21bce3b73dac02622f0a3c8d6 \ - --hash=sha256:b62cf8784eb6d35beaee1056d54caf94ec6ecf2b7552395e305518ab61eb8fd2 \ - --hash=sha256:a39f34c9b18e8f6794cca17bfbcd64572ca2482318db644268049f8c738f35a6 \ - --hash=sha256:883d68d48ca9ff3cb3d10c5fdebea02c79b48eecacdddbf7cce6e7cdbdc216b8 \ - --hash=sha256:cab7bc3d288d37a80aa8c0820033250c95e40b1c2b5c57cf59827b19c2a8b69d \ - --hash=sha256:56c767007ca959ca32f796b42379fc7e1ae2ed085d29f20b05b3fc394f3715cc \ - --hash=sha256:da2f331a01af232259a21573a01338530c6016dcfad74626c01330535bcd8628 \ + --hash=sha256:111c59897a452196116db12e7f608da472fbff000693a21040e35fc978b23430 \ + --hash=sha256:162e5675efb4704192411eaf8e00d07f7960b679cd3306e7efb120bb8d9456cc \ + --hash=sha256:165f22ab5a9513a3d7425ffb7fcc7955ed8ccaeef6d37e369d6cc1dff1582383 \ + --hash=sha256:17bb6600e2455993946385249a3c3d0af52cd70c1c1cdbf712e9d696d0b0bf1b \ --hash=sha256:19f93235ece6dbfc4036b5e4f6d8b13f0b8f2b3eeb8b0bd2936d406991bcdd40 \ - --hash=sha256:6698dbab5bcef8fdb570fc9d35fd9ac52041771bfcfe6fd0fc5f5c4e36f1e99d \ - --hash=sha256:329ff393441e75f10b673ae99ab45276887993d49e65f141da20d915c05aafd8 \ - --hash=sha256:eb072949b8ebf4082ae24289a2b0fd724da9adc8f22743409d6fd718ddb379df \ + --hash=sha256:1bef235a50a80f6aba05147002bc354559657cb6386dbd04d8e1c97d1d7cbe84 \ + --hash=sha256:258d1ea53464d29768bf25930f43291949f4c7becc706f6e220c515a63a24edd \ --hash=sha256:263a24f39f26e19ed7fc982d7859a36f17841b05bebad3eb47bb9cd2dd785351 \ - --hash=sha256:5152d50798c2fa5bd9b68ec68eb68a1b71b95126c1d70adaa1a08cd5eefdc23d \ - --hash=sha256:9d6a1e56dd267848edb824dbeb08cf5bac649e02ee0b03ba883ba3f4f0bd54f2 \ - --hash=sha256:73eaaf4bb04709f545606c1db2f65f4000e8a04cdbf3e00d165a23004692093e \ - --hash=sha256:162e5675efb4704192411eaf8e00d07f7960b679cd3306e7efb120bb8d9456cc \ - --hash=sha256:fab6b5e37715885c69f5d091f6ff229be71e235f272ebaa35158d5a46fd548a0 \ - --hash=sha256:a4aab31bd6d1057f287c96c0effca3a25584eb9cc702f282ecb96ded7814e830 \ - --hash=sha256:59aa31fe11a0e1d1bcc2ce37ed35fe2ac84cd65bb9036d049b1a1c39064d0f14 \ - --hash=sha256:05f32239aec25c5fb15f7948cffdc2dc0dac098e48b80a140e4ba32b572a2e7d \ - --hash=sha256:7c84f9d214f2d1de2fafebc17fa68ac3f6561a59e291553dfc45ad299f4898c1 \ - --hash=sha256:e77957d2ba17cada11be09a5066d93026cdb61ada7c8893101d7fe1c6e1f3925 \ + --hash=sha256:329ff393441e75f10b673ae99ab45276887993d49e65f141da20d915c05aafd8 \ --hash=sha256:42961609ac07c232a427da7c87a468d3c82fee6762c220f38e37cfdacb2b178d \ - --hash=sha256:ae07a3114313dd91fce686cab2f4c44af094398519af0e0f854bc707e1aeedf1 \ - --hash=sha256:d257c58d7b36a621dcce1d01476ad8b60f12d80eb1406aee4cf796f88b2ae482 \ - --hash=sha256:07c7211f9327d522c9c47560cae00a4ecf6687f4e02d779d035dd3177b41cb12 \ - --hash=sha256:8e7e9eca9b363dbedeceeadd8be97149d2499081f3c52d141d7cd1f395a91f83 \ - --hash=sha256:cb85b1d5702877c16f28d7b92ba030c1f49ebcc9b87d03d8c10bf45a2f1c7508 \ - --hash=sha256:4d4606c84d04b80f9138d72f1e28c6c02dc5ae0c7b8f3f8aaf89c681ce1cd1b1 \ - --hash=sha256:74eae563166ebf74e8d950ff359be037b85723d99ca83f57d9b244a871d6c13b \ + --hash=sha256:47f06fcbe8542b4d96d7392c476a74ada521c5aebdb41c3c0155f6595fc14c8d \ + --hash=sha256:48e500cf1c0984dacf1f28ea482c3cdbb4c2288d51c336c04bc64198ab21fc51 \ --hash=sha256:497852c5eaf1f0c2d88ab74a64a8097c099deac0c71de1cbcf18659a8a04a4b2 \ - --hash=sha256:258d1ea53464d29768bf25930f43291949f4c7becc706f6e220c515a63a24edd \ - --hash=sha256:111c59897a452196116db12e7f608da472fbff000693a21040e35fc978b23430 \ - --hash=sha256:17bb6600e2455993946385249a3c3d0af52cd70c1c1cdbf712e9d696d0b0bf1b \ - --hash=sha256:642050398583d61c9856210568eb09a8e4f2fe8224bf3be21b67a370e677eead \ + --hash=sha256:4d4606c84d04b80f9138d72f1e28c6c02dc5ae0c7b8f3f8aaf89c681ce1cd1b1 \ + --hash=sha256:5152d50798c2fa5bd9b68ec68eb68a1b71b95126c1d70adaa1a08cd5eefdc23d \ --hash=sha256:533efe6dc3a7cba5e2a84e38970786bb966306863e45f3db152007e9f48638a6 \ + --hash=sha256:56c767007ca959ca32f796b42379fc7e1ae2ed085d29f20b05b3fc394f3715cc \ --hash=sha256:5958dbf28b77ce2033482f6cb9ef04d43f5d8f4b7636e6963d5626f000efb23e \ + --hash=sha256:59aa31fe11a0e1d1bcc2ce37ed35fe2ac84cd65bb9036d049b1a1c39064d0f14 \ + --hash=sha256:642050398583d61c9856210568eb09a8e4f2fe8224bf3be21b67a370e677eead \ + --hash=sha256:6698dbab5bcef8fdb570fc9d35fd9ac52041771bfcfe6fd0fc5f5c4e36f1e99d \ + --hash=sha256:73eaaf4bb04709f545606c1db2f65f4000e8a04cdbf3e00d165a23004692093e \ + --hash=sha256:74eae563166ebf74e8d950ff359be037b85723d99ca83f57d9b244a871d6c13b \ + --hash=sha256:78c9ce98caaf82ac8484d269791c1b403d7598633e0e4e2fa1097baae244e2f1 \ + --hash=sha256:7c84f9d214f2d1de2fafebc17fa68ac3f6561a59e291553dfc45ad299f4898c1 \ + --hash=sha256:883d68d48ca9ff3cb3d10c5fdebea02c79b48eecacdddbf7cce6e7cdbdc216b8 \ + --hash=sha256:8e7e9eca9b363dbedeceeadd8be97149d2499081f3c52d141d7cd1f395a91f83 \ + --hash=sha256:90eecd93073922f085967f3ed3a98ba8c325cbbc8c1a204e300282abd2369e13 \ + --hash=sha256:97c839717bf8c8df3f6d983a20949c4fb22e2a34ee172e3e427ede363feda27b \ + --hash=sha256:9d6a1e56dd267848edb824dbeb08cf5bac649e02ee0b03ba883ba3f4f0bd54f2 \ + --hash=sha256:9f7d0cf072c6fbac3795b08c98ef9ea013f11db609659dcfc6b1f6cc31f9e181 \ + --hash=sha256:a39f34c9b18e8f6794cca17bfbcd64572ca2482318db644268049f8c738f35a6 \ + --hash=sha256:a4aab31bd6d1057f287c96c0effca3a25584eb9cc702f282ecb96ded7814e830 \ --hash=sha256:a6af77b6626ce92b5817bf294b4d45ec1a6161dba80fc2d82cdffdd6814fd023 \ - --hash=sha256:47f06fcbe8542b4d96d7392c476a74ada521c5aebdb41c3c0155f6595fc14c8d \ + --hash=sha256:a89bb9ee11177b2995d87186b1d9fa892d8ea725e85eab28c6525e4cc14ee048 \ + --hash=sha256:ae07a3114313dd91fce686cab2f4c44af094398519af0e0f854bc707e1aeedf1 \ + --hash=sha256:b27d3a23c79fa59557d2cc63a7e8bb4c7e022c018558eda36f9d7c4e6b99a6e0 \ + --hash=sha256:b3385b58b2fe408a13d084c14b8dcf468cd36cbbe774408250facc128f9fa75c \ + --hash=sha256:b62cf8784eb6d35beaee1056d54caf94ec6ecf2b7552395e305518ab61eb8fd2 \ + --hash=sha256:cab7bc3d288d37a80aa8c0820033250c95e40b1c2b5c57cf59827b19c2a8b69d \ + --hash=sha256:cb85b1d5702877c16f28d7b92ba030c1f49ebcc9b87d03d8c10bf45a2f1c7508 \ + --hash=sha256:d257c58d7b36a621dcce1d01476ad8b60f12d80eb1406aee4cf796f88b2ae482 \ + --hash=sha256:d593612758d0041cb13cb0003f7f8d3fabb7ad9319e651e78afae49b1cf5860e \ + --hash=sha256:da2f331a01af232259a21573a01338530c6016dcfad74626c01330535bcd8628 \ + --hash=sha256:dac7ee2f88b4d7bb12837989ca354c38d400eeb21bce3b73dac02622f0a3c8d6 \ + --hash=sha256:e77957d2ba17cada11be09a5066d93026cdb61ada7c8893101d7fe1c6e1f3925 \ --hash=sha256:e7800e6c6b5dc4b0ca7cc7370f770f53ac83886b76afda0848065a674231e856 \ - --hash=sha256:165f22ab5a9513a3d7425ffb7fcc7955ed8ccaeef6d37e369d6cc1dff1582383 + --hash=sha256:e7b607f0e14f2a4cf7e78a05ebd13df6144acfba87cb90842e70d3f125d9f53f \ + --hash=sha256:eb072949b8ebf4082ae24289a2b0fd724da9adc8f22743409d6fd718ddb379df \ + --hash=sha256:eb36a08859b9432d94ea6b26ec41a2f98f83f14868c91321d0c1e11f672eeae7 \ + --hash=sha256:f24e8e17035200a465c178e9ea945527ad0738118694184c450f1192a452ff25 \ + --hash=sha256:fab6b5e37715885c69f5d091f6ff229be71e235f272ebaa35158d5a46fd548a0 # via psycopg pyarrow==19.0.0 \ --hash=sha256:239ca66d9a05844bdf5af128861af525e14df3c9591bcc05bac25918e650d3a2 \ @@ -2030,81 +2069,46 @@ pyparsing==3.3.2 \ --hash=sha256:c777f4d763f140633dcb6d8a3eda953bf7a214dc4eff598413c070bcdc117cbc # via matplotlib pyqt5==5.15.11 \ - --hash=sha256:6cd75628f6e732b1ffcfe709ab833a0716c0445d7aec8046a48d5843352becb6 \ --hash=sha256:6cd75628f6e732b1ffcfe709ab833a0716c0445d7aec8046a48d5843352becb6 \ --hash=sha256:76be0322ceda5deecd1708a8d628e698089a1cea80d1a49d242a6d579a40babd \ - --hash=sha256:76be0322ceda5deecd1708a8d628e698089a1cea80d1a49d242a6d579a40babd \ - --hash=sha256:bdde598a3bb95022131a5c9ea62e0a96bd6fb28932cc1619fd7ba211531b7517 \ --hash=sha256:bdde598a3bb95022131a5c9ea62e0a96bd6fb28932cc1619fd7ba211531b7517 \ --hash=sha256:c8b03dd9380bb13c804f0bdb0f4956067f281785b5e12303d529f0462f9afdc2 \ - --hash=sha256:c8b03dd9380bb13c804f0bdb0f4956067f281785b5e12303d529f0462f9afdc2 \ - --hash=sha256:cd672a6738d1ae33ef7d9efa8e6cb0a1525ecf53ec86da80a9e1b6ec38c8d0f1 \ --hash=sha256:cd672a6738d1ae33ef7d9efa8e6cb0a1525ecf53ec86da80a9e1b6ec38c8d0f1 \ - --hash=sha256:fda45743ebb4a27b4b1a51c6d8ef455c4c1b5d610c90d2934c7802b5c1557c52 \ --hash=sha256:fda45743ebb4a27b4b1a51c6d8ef455c4c1b5d610c90d2934c7802b5c1557c52 # via mozdetect pyqt5-qt5==5.15.19 \ --hash=sha256:31421d9c31fb29a8faee4b8b3c32658fb51a9e8c4c708075121162fa44faf80e \ - --hash=sha256:31421d9c31fb29a8faee4b8b3c32658fb51a9e8c4c708075121162fa44faf80e \ - --hash=sha256:66fa299dcdea1f430edbd6f6ca3dcb20430f19c508d13e3aa851d19034b7be7e \ --hash=sha256:66fa299dcdea1f430edbd6f6ca3dcb20430f19c508d13e3aa851d19034b7be7e \ - --hash=sha256:cac6b78e4805848c25979a0622660251070781b6b4f810688a960cb44d1ae5a2 \ --hash=sha256:cac6b78e4805848c25979a0622660251070781b6b4f810688a960cb44d1ae5a2 # via # mozdetect # pyqt5 pyqt5-sip==12.18.0 \ --hash=sha256:13c32e9025d0ab5fe960ef64dcb4c6f7ec26156ddce2cf2f195600aa26e8f9fe \ - --hash=sha256:13c32e9025d0ab5fe960ef64dcb4c6f7ec26156ddce2cf2f195600aa26e8f9fe \ - --hash=sha256:163c2bba5e637c2222ec17d82a2c5aa158184a191923eb7d137cf4cfa0399529 \ --hash=sha256:163c2bba5e637c2222ec17d82a2c5aa158184a191923eb7d137cf4cfa0399529 \ --hash=sha256:521729e4ce44db555005f4e6987c4a5164d45ea03f5a7d08519813d4776acd15 \ - --hash=sha256:521729e4ce44db555005f4e6987c4a5164d45ea03f5a7d08519813d4776acd15 \ - --hash=sha256:65f257e28d06a01c2a9a7c0b2faf2af1dbf25a1420a5a9d905a54aaddce74d79 \ --hash=sha256:65f257e28d06a01c2a9a7c0b2faf2af1dbf25a1420a5a9d905a54aaddce74d79 \ --hash=sha256:6d948f1be619c645cd3bda54952bfdc1aef7c79242dccea6a6858748e61114b9 \ - --hash=sha256:6d948f1be619c645cd3bda54952bfdc1aef7c79242dccea6a6858748e61114b9 \ - --hash=sha256:71c37db75a0664325de149f43e2a712ec5fa1f90429a21dafbca005cb6767f94 \ --hash=sha256:71c37db75a0664325de149f43e2a712ec5fa1f90429a21dafbca005cb6767f94 \ --hash=sha256:8372ec8704bfd5e09942d0d055a1657eb4f702f4b30847a5e59df0496f99d67f \ - --hash=sha256:8372ec8704bfd5e09942d0d055a1657eb4f702f4b30847a5e59df0496f99d67f \ - --hash=sha256:9254e5dd7676b76503ba20edcc919e7ac4a97b6c70a6fb2f9dba9e13b4c60509 \ --hash=sha256:9254e5dd7676b76503ba20edcc919e7ac4a97b6c70a6fb2f9dba9e13b4c60509 \ --hash=sha256:92abe984becbde768954d6d0951f56d80a9868d2fd9e738e61fc944f0ff83dd6 \ - --hash=sha256:92abe984becbde768954d6d0951f56d80a9868d2fd9e738e61fc944f0ff83dd6 \ - --hash=sha256:95bba4670ecf5cba73958b85aa2087c17838a402ed251c38e68060c7665c998b \ --hash=sha256:95bba4670ecf5cba73958b85aa2087c17838a402ed251c38e68060c7665c998b \ --hash=sha256:993fe3ed9a62a92e770f32d5344e3df56c2cacf1471f01b7feaf04818a2df1c4 \ - --hash=sha256:993fe3ed9a62a92e770f32d5344e3df56c2cacf1471f01b7feaf04818a2df1c4 \ - --hash=sha256:9b689e02e400abd1ce0a30cd6eae8eceabcf1bbba0395cb5c86e64ba74351d68 \ --hash=sha256:9b689e02e400abd1ce0a30cd6eae8eceabcf1bbba0395cb5c86e64ba74351d68 \ --hash=sha256:a2a0278091d067b17855047ed8bd557e5ca62308a7d9fb5200451d0bd9090afc \ - --hash=sha256:a2a0278091d067b17855047ed8bd557e5ca62308a7d9fb5200451d0bd9090afc \ - --hash=sha256:aac4adc37df2f2ac1dc259409be1900f07332d140a12c9db7c84112cef64ff59 \ --hash=sha256:aac4adc37df2f2ac1dc259409be1900f07332d140a12c9db7c84112cef64ff59 \ --hash=sha256:ac0be1a8ce145ed78c7e8d45243749405bee7e3a87e9810b0542bca010c50bd7 \ - --hash=sha256:ac0be1a8ce145ed78c7e8d45243749405bee7e3a87e9810b0542bca010c50bd7 \ - --hash=sha256:b29e4cda24748e59e5bd1bdad4812091a86b4b5b08c38b7f781eb55a5166f2b7 \ --hash=sha256:b29e4cda24748e59e5bd1bdad4812091a86b4b5b08c38b7f781eb55a5166f2b7 \ --hash=sha256:b4b743566f67cabfa7b0ba2da30b46d9d635d16cd5bc8cdcec83f620ed14dd93 \ - --hash=sha256:b4b743566f67cabfa7b0ba2da30b46d9d635d16cd5bc8cdcec83f620ed14dd93 \ - --hash=sha256:bbec4c14903bcd585b4e1ee50edccfe224c8c0ee8004a072143993b4eb954442 \ --hash=sha256:bbec4c14903bcd585b4e1ee50edccfe224c8c0ee8004a072143993b4eb954442 \ --hash=sha256:bd9e3c6f81346f1b08d6db02305cdee20c009b43aa083d44ee2de47a7da0e123 \ - --hash=sha256:bd9e3c6f81346f1b08d6db02305cdee20c009b43aa083d44ee2de47a7da0e123 \ - --hash=sha256:c738949863d88b78f86f28e13151989ca3b1a302934811af41856dc8a27838bd \ --hash=sha256:c738949863d88b78f86f28e13151989ca3b1a302934811af41856dc8a27838bd \ --hash=sha256:c969631ada7293a81e1012b2264a62d69a91995b517586489dfe24421b87b9af \ - --hash=sha256:c969631ada7293a81e1012b2264a62d69a91995b517586489dfe24421b87b9af \ - --hash=sha256:d84ac384a63285132e67762c87681191c25e28a1df7560287ec3889d9eb223b5 \ --hash=sha256:d84ac384a63285132e67762c87681191c25e28a1df7560287ec3889d9eb223b5 \ --hash=sha256:dc5c30bb9bd8cca6e13d2fedac6e2a75fe2168d798d66f76e74835546b025027 \ - --hash=sha256:dc5c30bb9bd8cca6e13d2fedac6e2a75fe2168d798d66f76e74835546b025027 \ - --hash=sha256:dd855149c724634eb1f92d10e04e1be0751068a8521d5f9f06e5c2dbe32fd89f \ --hash=sha256:dd855149c724634eb1f92d10e04e1be0751068a8521d5f9f06e5c2dbe32fd89f \ --hash=sha256:ead5e0a64ad852ac60797989d8444a6a5bd834768536b04a07b40b2937d922f6 \ - --hash=sha256:ead5e0a64ad852ac60797989d8444a6a5bd834768536b04a07b40b2937d922f6 \ - --hash=sha256:fdb45c7cd2af7eccd7370b994d432bfc7965079f845392760724f26771bb59dc \ --hash=sha256:fdb45c7cd2af7eccd7370b994d432bfc7965079f845392760724f26771bb59dc # via pyqt5 python-dateutil==2.9.0.post0 \ @@ -2658,7 +2662,7 @@ typing-extensions==4.15.0 \ --hash=sha256:0cea48d173cc12fa28ecabc3b837ea3cf6f38c6d1136f85cbaaf598984861466 \ --hash=sha256:f0fa19c6845758ab08074a0cfa8b7aecb71c999ca73d62883bc25cc018c4e548 # via - # aiosignal + # opentelemetry-api # pygithub tzdata==2025.2 \ --hash=sha256:1a403fada01ff9221ca8044d701868fa132215d84beb92242d9acd2147f667a8 \ diff --git a/tests/etl/taskcluster_pulse/test_handler.py b/tests/etl/taskcluster_pulse/test_handler.py index ecfe4e0ce17..71b69386471 100644 --- a/tests/etl/taskcluster_pulse/test_handler.py +++ b/tests/etl/taskcluster_pulse/test_handler.py @@ -1,6 +1,8 @@ import pytest +from treeherder.etl.taskcluster_pulse import handler as tc_handler from treeherder.etl.taskcluster_pulse.handler import handle_message, handle_task_defined +from treeherder.utils.logging_context import get_log_labels @pytest.mark.asyncio @@ -43,6 +45,45 @@ async def test_handle_message_routes_task_defined(): assert result[0]["result"] == "unknown" +@pytest.mark.asyncio +async def test_handle_message_sets_log_context(monkeypatch): + """handle_message wraps processing in a log_context carrying task_id/run_id.""" + captured = {} + + def capture_labels(*args, **kwargs): + captured.update(get_log_labels()) + return {"state": "unscheduled", "result": "unknown"} + + monkeypatch.setattr(tc_handler, "handle_task_defined", capture_labels) + + task = { + "metadata": {"name": "t", "description": "d", "owner": "o@example.com"}, + "created": "2025-01-01T00:00:00.000Z", + "workerType": "test-worker", + "tags": {}, + "routes": ["tc-treeherder.v2.autoland.abc123"], + "extra": {"treeherder": {"symbol": "T", "tier": 1}}, + } + message = { + "exchange": "exchange/taskcluster-queue/v1/task-defined", + "root_url": "https://firefox-ci-tc.services.mozilla.com", + "payload": { + "runId": 0, + "status": {"taskId": "AJBb7wqZT6K9kz4niYAatg", "state": "unscheduled", "runs": []}, + }, + } + + await handle_message(message, task) + + assert captured == { + "task_id": "AJBb7wqZT6K9kz4niYAatg", + "run_id": "0", + "component": "ingestion", + } + # context is cleaned up after the handler returns + assert get_log_labels() == {} + + def test_handle_task_defined(): push_info = { "project": "autoland", diff --git a/tests/utils/test_gcp_logging.py b/tests/utils/test_gcp_logging.py new file mode 100644 index 00000000000..ffd69feceb7 --- /dev/null +++ b/tests/utils/test_gcp_logging.py @@ -0,0 +1,51 @@ +import io +import json +import logging + +import pytest + +pytest.importorskip("google.cloud.logging_v2") + +from treeherder.utils.gcp_logging import ContextLabelStructuredLogHandler +from treeherder.utils.logging_context import log_context + + +def emit_within_context(**context_labels): + """Emit one log line through the handler inside a log_context, return its GCP labels.""" + stream = io.StringIO() + handler = ContextLabelStructuredLogHandler(stream=stream) + logger = logging.getLogger("test.gcp_logging") + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + with log_context(**context_labels): + logger.info("hello world") + for line in stream.getvalue().splitlines(): + entry = json.loads(line) + if entry.get("message") == "hello world": + return entry.get("logging.googleapis.com/labels", {}) + raise AssertionError("log line not found in handler output") + + +def test_handler_emits_context_labels_as_gcp_labels(): + labels = emit_within_context(task_id="ABC", run_id="0", component="failureline") + assert labels["task_id"] == "ABC" + assert labels["run_id"] == "0" + assert labels["component"] == "failureline" + + +def test_handler_emits_no_task_labels_without_context(): + stream = io.StringIO() + handler = ContextLabelStructuredLogHandler(stream=stream) + logger = logging.getLogger("test.gcp_logging.nolabels") + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + logger.info("plain message") + for line in stream.getvalue().splitlines(): + entry = json.loads(line) + if entry.get("message") == "plain message": + labels = entry.get("logging.googleapis.com/labels", {}) + assert "task_id" not in labels + return + raise AssertionError("log line not found in handler output") diff --git a/tests/utils/test_logging_context.py b/tests/utils/test_logging_context.py new file mode 100644 index 00000000000..ec49d2a50f7 --- /dev/null +++ b/tests/utils/test_logging_context.py @@ -0,0 +1,108 @@ +import logging + +import pytest + +from treeherder.model import models as th_models +from treeherder.utils.logging_context import ( + apply_context_labels, + get_log_labels, + job_log_labels, + log_context, +) + + +def make_record(): + return logging.LogRecord( + name="treeherder.test", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="hello", + args=(), + exc_info=None, + ) + + +def test_get_log_labels_empty_outside_context(): + assert get_log_labels() == {} + + +def test_log_context_sets_labels(): + with log_context(task_id="ABC", run_id="0"): + assert get_log_labels() == {"task_id": "ABC", "run_id": "0"} + # restored after the block exits + assert get_log_labels() == {} + + +def test_log_context_merges_and_restores_nested(): + with log_context(task_id="ABC", component="ingestion"): + with log_context(run_id="2", component="failureline"): + assert get_log_labels() == { + "task_id": "ABC", + "run_id": "2", + "component": "failureline", + } + # inner block unwinds, outer labels remain + assert get_log_labels() == {"task_id": "ABC", "component": "ingestion"} + assert get_log_labels() == {} + + +def test_log_context_ignores_none_values(): + with log_context(task_id="ABC", run_id=None, job_id=None): + assert get_log_labels() == {"task_id": "ABC"} + + +def test_get_log_labels_returns_a_copy(): + with log_context(task_id="ABC"): + labels = get_log_labels() + labels["task_id"] = "MUTATED" + assert get_log_labels() == {"task_id": "ABC"} + + +def test_log_context_usable_as_decorator(): + @log_context(component="failureline") + def do_work(): + return get_log_labels() + + assert do_work() == {"component": "failureline"} + assert get_log_labels() == {} + + +def test_apply_context_labels_stashes_current_labels_on_record(): + record = make_record() + with log_context(task_id="ABC", run_id="0"): + apply_context_labels(record) + assert record.labels == {"task_id": "ABC", "run_id": "0"} + + +def test_apply_context_labels_preserves_per_call_labels(): + record = make_record() + # a label set explicitly on the call (via extra={"labels": ...}) wins over context + record.labels = {"task_id": "EXPLICIT"} + with log_context(task_id="CONTEXT", run_id="0"): + apply_context_labels(record) + assert record.labels == {"task_id": "EXPLICIT", "run_id": "0"} + + +def test_apply_context_labels_no_context_is_noop(): + record = make_record() + apply_context_labels(record) + assert getattr(record, "labels", {}) == {} + + +@pytest.mark.django_db +def test_job_log_labels_with_taskcluster_metadata(test_job): + meta = test_job.taskcluster_metadata + assert job_log_labels(test_job) == { + "task_id": meta.task_id, + "run_id": str(meta.retry_id), + "job_id": str(test_job.id), + } + + +@pytest.mark.django_db +def test_job_log_labels_without_metadata_omits_task_and_run(test_job): + th_models.TaskclusterMetadata.objects.filter(job=test_job).delete() + # re-fetch to drop the cached reverse relation + job = th_models.Job.objects.get(id=test_job.id) + assert job_log_labels(job) == {"job_id": str(job.id)} diff --git a/treeherder/config/settings.py b/treeherder/config/settings.py index c1a2d689521..cf3866c247e 100644 --- a/treeherder/config/settings.py +++ b/treeherder/config/settings.py @@ -25,6 +25,11 @@ DEBUG = env.bool("TREEHERDER_DEBUG", default=False) LOGGING_LEVEL = env("LOGGING_LEVEL", default="INFO") +# When enabled, the `treeherder` logger emits GCP-structured JSON to stdout with +# task_id/run_id/component attached as queryable Cloud Logging labels (see +# treeherder.utils.gcp_logging). Off by default so local/dev stays human-readable. +GCP_STRUCTURED_LOGGING = env.bool("GCP_STRUCTURED_LOGGING", default=False) + NEW_RELIC_INSIGHTS_API_KEY = env("NEW_RELIC_INSIGHTS_API_KEY", default=None) NEW_RELIC_INSIGHTS_API_URL = "https://insights-api.newrelic.com/v1/accounts/677903/query" @@ -251,6 +256,16 @@ }, } +if GCP_STRUCTURED_LOGGING: + # Route the `treeherder` logger through the GCP-structured handler so its + # records carry task_id/run_id/component labels. Added conditionally so the + # google-cloud-logging import only happens when the feature is enabled. + LOGGING["handlers"]["gcp_structured"] = { + "class": "treeherder.utils.gcp_logging.ContextLabelStructuredLogHandler", + "level": "DEBUG", + } + LOGGING["loggers"]["treeherder"]["handlers"] = ["gcp_structured"] + # SECURITY CSRF_TRUSTED_ORIGINS = env.list( diff --git a/treeherder/etl/taskcluster_pulse/handler.py b/treeherder/etl/taskcluster_pulse/handler.py index 1bbc13da36c..e33166e0aef 100644 --- a/treeherder/etl/taskcluster_pulse/handler.py +++ b/treeherder/etl/taskcluster_pulse/handler.py @@ -12,6 +12,7 @@ from treeherder.etl.schema import get_json_schema from treeherder.etl.taskcluster_pulse.parse_route import parse_route +from treeherder.utils.logging_context import log_context env = environ.Env() logger = logging.getLogger(__name__) @@ -176,45 +177,51 @@ async def handle_message(message, task_definition=None): task_id = message["payload"]["status"]["taskId"] # task-defined messages don't have runId since the task has no runs yet run_id = message["payload"].get("runId", 0) - if task_definition: - task = task_definition - else: - async_queue = taskcluster.aio.Queue({"rootUrl": message["root_url"]}, session=session) - with settings.STATSD_CLIENT.timer("taskcluster_fetch_definition"): - task = await async_queue.task(task_id) - try: - parsed_route = parse_route_info("tc-treeherder", task_id, task["routes"], task) - except PulseHandlerError as e: - logger.debug("%s", str(e)) - return jobs + # Attach task_id/run_id as GCP log labels to every line emitted while + # ingesting this task (route parsing, task filtering, validation, etc.). + with log_context(task_id=task_id, run_id=str(run_id), component="ingestion"): + if task_definition: + task = task_definition + else: + async_queue = taskcluster.aio.Queue( + {"rootUrl": message["root_url"]}, session=session + ) + with settings.STATSD_CLIENT.timer("taskcluster_fetch_definition"): + task = await async_queue.task(task_id) - if ignore_task(task, task_id, message["root_url"], parsed_route["project"]): - return jobs - - logger.debug("Message received for task %s", task_id) + try: + parsed_route = parse_route_info("tc-treeherder", task_id, task["routes"], task) + except PulseHandlerError as e: + logger.debug("%s", str(e)) + return jobs + + if ignore_task(task, task_id, message["root_url"], parsed_route["project"]): + return jobs + + logger.debug("Message received for task %s", task_id) + + # Validation failures are common and logged, so do nothing more. + if not validate_task(task, task_id, run_id): + return jobs + + task_type = EXCHANGE_EVENT_MAP.get(message["exchange"]) + + if not task_type: + raise Exception("Unknown exchange: {exchange}".format(exchange=message["exchange"])) + elif task_type == "unscheduled": + jobs.append(handle_task_defined(parsed_route, task, message)) + elif task_type == "pending": + jobs.append(handle_task_pending(parsed_route, task, message)) + elif task_type == "running": + jobs.append(handle_task_running(parsed_route, task, message)) + elif task_type in ("completed", "failed"): + jobs.append(await handle_task_completed(parsed_route, task, message, session)) + elif task_type == "exception": + jobs.append(await handle_task_exception(parsed_route, task, message, session)) - # Validation failures are common and logged, so do nothing more. - if not validate_task(task, task_id, run_id): return jobs - task_type = EXCHANGE_EVENT_MAP.get(message["exchange"]) - - if not task_type: - raise Exception("Unknown exchange: {exchange}".format(exchange=message["exchange"])) - elif task_type == "unscheduled": - jobs.append(handle_task_defined(parsed_route, task, message)) - elif task_type == "pending": - jobs.append(handle_task_pending(parsed_route, task, message)) - elif task_type == "running": - jobs.append(handle_task_running(parsed_route, task, message)) - elif task_type in ("completed", "failed"): - jobs.append(await handle_task_completed(parsed_route, task, message, session)) - elif task_type == "exception": - jobs.append(await handle_task_exception(parsed_route, task, message, session)) - - return jobs - # Builds the basic Treeherder job message that's universal for all # messsage types. diff --git a/treeherder/log_parser/tasks.py b/treeherder/log_parser/tasks.py index 827a2bb2e50..e52714a1433 100644 --- a/treeherder/log_parser/tasks.py +++ b/treeherder/log_parser/tasks.py @@ -11,6 +11,7 @@ LogSizeError, ) from treeherder.model.models import Job, JobLog +from treeherder.utils.logging_context import job_log_labels, log_context from treeherder.workers.task import retryable_task from . import failureline, intermittents @@ -23,59 +24,63 @@ def parse_logs(job_id, job_log_ids, priority): newrelic.agent.add_custom_attribute("job_id", str(job_id)) job = Job.objects.get(id=job_id) - job_logs = JobLog.objects.filter(id__in=job_log_ids, job=job) - if len(job_log_ids) != len(job_logs): - logger.warning( - "Failed to load all expected job ids: %s", ", ".join([str(j) for j in job_log_ids]) - ) + # Attach task_id/run_id/job_id as GCP log labels to every line emitted while + # parsing this job's logs (including deeper failure-line processing). + with log_context(**job_log_labels(job), component="log_parser"): + job_logs = JobLog.objects.filter(id__in=job_log_ids, job=job) - parser_tasks = { - "errorsummary_json": store_failure_lines, - "live_backing_log": post_log_artifacts, - } - - # We don't want to stop parsing logs for most Exceptions however we still - # need to know one occurred so we can skip further steps and reraise to - # trigger the retry decorator. - first_exception = None - completed_names = set() - for job_log in job_logs: - newrelic.agent.add_custom_attribute(f"job_log_{job_log.name}_url", job_log.url) - logger.info("parser_task for %s", job_log.id) - - # Only parse logs which haven't yet been processed or else failed on the last attempt. - if job_log.status not in (JobLog.PENDING, JobLog.FAILED): - logger.info( - f"Skipping parsing for job %s since log already processed. Log Status: {job_log.status}", - job_log.id, + if len(job_log_ids) != len(job_logs): + logger.warning( + "Failed to load all expected job ids: %s", ", ".join([str(j) for j in job_log_ids]) ) - continue - - parser = parser_tasks.get(job_log.name) - if not parser: - continue - - try: - parser(job_log) - except Exception as e: - if isinstance(e, SoftTimeLimitExceeded): - # stop parsing further logs but raise so NewRelic and - # Papertrail will still show output - raise - - if first_exception is None: - first_exception = e - - # track the exception on NewRelic but don't stop parsing future - # log lines. - newrelic.agent.notice_error() - else: - completed_names.add(job_log.name) - - # Raise so we trigger the retry decorator. - if first_exception: - raise first_exception + + parser_tasks = { + "errorsummary_json": store_failure_lines, + "live_backing_log": post_log_artifacts, + } + + # We don't want to stop parsing logs for most Exceptions however we still + # need to know one occurred so we can skip further steps and reraise to + # trigger the retry decorator. + first_exception = None + completed_names = set() + for job_log in job_logs: + newrelic.agent.add_custom_attribute(f"job_log_{job_log.name}_url", job_log.url) + logger.info("parser_task for %s", job_log.id) + + # Only parse logs which haven't yet been processed or else failed on the last attempt. + if job_log.status not in (JobLog.PENDING, JobLog.FAILED): + logger.info( + f"Skipping parsing for job %s since log already processed. Log Status: {job_log.status}", + job_log.id, + ) + continue + + parser = parser_tasks.get(job_log.name) + if not parser: + continue + + try: + parser(job_log) + except Exception as e: + if isinstance(e, SoftTimeLimitExceeded): + # stop parsing further logs but raise so NewRelic and + # Papertrail will still show output + raise + + if first_exception is None: + first_exception = e + + # track the exception on NewRelic but don't stop parsing future + # log lines. + newrelic.agent.notice_error() + else: + completed_names.add(job_log.name) + + # Raise so we trigger the retry decorator. + if first_exception: + raise first_exception def store_failure_lines(job_log): diff --git a/treeherder/utils/gcp_logging.py b/treeherder/utils/gcp_logging.py new file mode 100644 index 00000000000..7aa9cd66f42 --- /dev/null +++ b/treeherder/utils/gcp_logging.py @@ -0,0 +1,25 @@ +"""GCP-structured logging handler that stamps log-context labels onto records. + +This module imports ``google-cloud-logging`` and is only referenced from the +Django ``LOGGING`` config when structured logging is enabled, so environments +without the dependency (or with the feature turned off) never import it. +""" + +from google.cloud.logging_v2.handlers import StructuredLogHandler + +from treeherder.utils.logging_context import apply_context_labels + + +class ContextLabelStructuredLogHandler(StructuredLogHandler): + """Emit GCP-structured logs with the active ``log_context`` labels attached. + + Labels are applied in ``handle`` — before the handler's filter phase — so + google-cloud-logging's built-in ``CloudLoggingFilter`` reads ``record.labels`` + and emits them under ``logging.googleapis.com/labels`` (queryable in Cloud + Logging). Applying them later (e.g. via a handler-level filter or in + ``emit``) is too late: ``CloudLoggingFilter`` has already run. + """ + + def handle(self, record): + apply_context_labels(record) + return super().handle(record) diff --git a/treeherder/utils/logging_context.py b/treeherder/utils/logging_context.py new file mode 100644 index 00000000000..31aefe2440c --- /dev/null +++ b/treeherder/utils/logging_context.py @@ -0,0 +1,66 @@ +"""Centralized logging context for attaching structured labels to log records. + +Metadata (task_id, run_id, job_id, component) is set once at a task or ingestion +boundary via ``log_context(...)`` and automatically propagates to every log +record emitted within that scope. ``apply_context_labels`` copies the active +labels onto a record so a GCP-structured handler can promote them to queryable +Cloud Logging labels (see ``treeherder.utils.gcp_logging``). +""" + +import contextlib +from contextvars import ContextVar + +from django.core.exceptions import ObjectDoesNotExist + +# Holds the labels active for the current thread / async task. Never mutated in +# place; each ``log_context`` sets a fresh dict and restores the prior one. +_log_labels: ContextVar[dict] = ContextVar("log_labels", default={}) + + +def get_log_labels() -> dict: + """Return a copy of the labels active in the current context.""" + return dict(_log_labels.get()) + + +@contextlib.contextmanager +def log_context(**labels): + """Merge ``labels`` onto the active context for the duration of the block. + + ``None`` values are ignored. Usable as a context manager or a decorator. + Nested contexts compose; the previous labels are restored on exit. + """ + merged = {**_log_labels.get(), **{k: v for k, v in labels.items() if v is not None}} + token = _log_labels.set(merged) + try: + yield + finally: + _log_labels.reset(token) + + +def job_log_labels(job) -> dict: + """Resolve GCP labels for a Job: task_id, run_id and job_id. + + task_id/run_id are omitted for jobs without Taskcluster metadata (e.g. + non-Taskcluster or not-yet-ingested jobs). + """ + labels = {"job_id": str(job.id)} + try: + metadata = job.taskcluster_metadata + except ObjectDoesNotExist: + return labels + labels["task_id"] = metadata.task_id + labels["run_id"] = str(metadata.retry_id) + return labels + + +def apply_context_labels(record): + """Merge the active context labels onto ``record.labels`` in place. + + Labels set explicitly on the record (via ``extra={"labels": ...}``) take + precedence over ambient context labels. Returns the record. + """ + context = get_log_labels() + if context: + existing = getattr(record, "labels", {}) or {} + record.labels = {**context, **existing} + return record