)]}'
{"/PATCHSET_LEVEL":[{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"6c4549d2ba5a5e70ef3cb3d770b0ee57c12d76ab","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":11,"id":"ae127a12_877bee72","updated":"2022-02-24 20:34:39.000000000","message":"recheck","commit_id":"030ef820a0923cb1c40469e282440e3960e94c93"}],"doc/source/reference/monitoring.rst":[{"author":{"_account_id":7118,"name":"Ian Wienand","email":"iwienand@redhat.com","username":"iwienand"},"change_message_id":"85e5195057b445b210da11f2fe26648250aed296","unresolved":false,"context_lines":[{"line_number":431,"context_line":""},{"line_number":432,"context_line":"      A counter for each reporter holding the count of reports done."},{"line_number":433,"context_line":""},{"line_number":434,"context_line":"As an example, given a job named `myjob` in `mytenant` triggered by a"},{"line_number":435,"context_line":"change to `myproject` on the `master` branch in the `gate` pipeline"},{"line_number":436,"context_line":"which took 40 seconds to build, the Zuul scheduler will emit the"},{"line_number":437,"context_line":"following statsd events:"},{"line_number":438,"context_line":""},{"line_number":439,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.project.example_com.myproject.master.job.myjob.SUCCESS`` +1"},{"line_number":440,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.project.example_com.myproject.master.job.myjob.SUCCESS``  40 seconds"},{"line_number":441,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.all_jobs`` +1"}],"source_content_type":"text/x-rst","patch_set":8,"id":"9f560f44_52c6a417","line":441,"range":{"start_line":434,"start_character":0,"end_line":441,"end_character":54},"updated":"2020-09-28 00:17:22.000000000","message":"might be nice to add details here?  I find these sorts of practical examples more useful as a first example that the raw docs.","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"fe3d08f292c567f40d3fc0b0adfdc039f82d5312","unresolved":false,"context_lines":[{"line_number":431,"context_line":""},{"line_number":432,"context_line":"      A counter for each reporter holding the count of reports done."},{"line_number":433,"context_line":""},{"line_number":434,"context_line":"As an example, given a job named `myjob` in `mytenant` triggered by a"},{"line_number":435,"context_line":"change to `myproject` on the `master` branch in the `gate` pipeline"},{"line_number":436,"context_line":"which took 40 seconds to build, the Zuul scheduler will emit the"},{"line_number":437,"context_line":"following statsd events:"},{"line_number":438,"context_line":""},{"line_number":439,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.project.example_com.myproject.master.job.myjob.SUCCESS`` +1"},{"line_number":440,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.project.example_com.myproject.master.job.myjob.SUCCESS``  40 seconds"},{"line_number":441,"context_line":"  * ``zuul.tenant.mytenant.pipeline.gate.all_jobs`` +1"}],"source_content_type":"text/x-rst","patch_set":8,"id":"9f560f44_5a7cf66f","line":441,"range":{"start_line":434,"start_character":0,"end_line":441,"end_character":54},"in_reply_to":"9f560f44_52c6a417","updated":"2020-09-28 10:20:47.000000000","message":"Done","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"}],"zuul/manager/__init__.py":[{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"0038a0c8ab993a3cc4805ef64549f6adc0257c28","unresolved":false,"context_lines":[{"line_number":194,"context_line":"        if len(action_reporters) \u003e 0:"},{"line_number":195,"context_line":"            for reporter in action_reporters:"},{"line_number":196,"context_line":"                try:"},{"line_number":197,"context_line":"                    self.log.debug(\"Reporting to %s started\", reporter.name)"},{"line_number":198,"context_line":"                    start \u003d time.monotonic()"},{"line_number":199,"context_line":"                    ret \u003d reporter.report(item)"},{"line_number":200,"context_line":"                    duration \u003d (time.monotonic() - start) * 1000"}],"source_content_type":"text/x-python","patch_set":3,"id":"9f560f44_72aa7171","line":197,"updated":"2020-09-17 12:34:13.000000000","message":"We need to use log instead of self.log to have annotated logging.","commit_id":"801796655e1a331e35b53b6ca7e9ced64fa74527"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"eb790c5b48adbbf98fe30e957cd2cddf5289f40c","unresolved":false,"context_lines":[{"line_number":194,"context_line":"        if len(action_reporters) \u003e 0:"},{"line_number":195,"context_line":"            for reporter in action_reporters:"},{"line_number":196,"context_line":"                try:"},{"line_number":197,"context_line":"                    self.log.debug(\"Reporting to %s started\", reporter.name)"},{"line_number":198,"context_line":"                    start \u003d time.monotonic()"},{"line_number":199,"context_line":"                    ret \u003d reporter.report(item)"},{"line_number":200,"context_line":"                    duration \u003d (time.monotonic() - start) * 1000"}],"source_content_type":"text/x-python","patch_set":3,"id":"9f560f44_124e95c1","line":197,"in_reply_to":"9f560f44_72aa7171","updated":"2020-09-17 12:43:33.000000000","message":"Done","commit_id":"801796655e1a331e35b53b6ca7e9ced64fa74527"},{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"05a1422b434dd2570fa3512f8b0112b2fe907c6d","unresolved":false,"context_lines":[{"line_number":199,"context_line":"                    ret \u003d reporter.report(item)"},{"line_number":200,"context_line":"                    duration \u003d (time.monotonic() - start) * 1000"},{"line_number":201,"context_line":"                    log.debug(\"Reporting to %s finished in %sms\","},{"line_number":202,"context_line":"                              reporter.name, duration)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    self.sched.statsd.timing("}],"source_content_type":"text/x-python","patch_set":6,"id":"9f560f44_ce4d8cc6","line":202,"updated":"2020-09-18 06:01:00.000000000","message":"duration is a float. Since we\u0027re already in ms resolution we should cast it to int to avoid cluttering the log with too precise float formatting.","commit_id":"e7c86ed52e530e276a8a2d1bfe7c1f975214dd31"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"694e59c242b03a7462f747678a6b06c342837f95","unresolved":false,"context_lines":[{"line_number":199,"context_line":"                    ret \u003d reporter.report(item)"},{"line_number":200,"context_line":"                    duration \u003d (time.monotonic() - start) * 1000"},{"line_number":201,"context_line":"                    log.debug(\"Reporting to %s finished in %sms\","},{"line_number":202,"context_line":"                              reporter.name, duration)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    self.sched.statsd.timing("}],"source_content_type":"text/x-python","patch_set":6,"id":"9f560f44_e9f5eacd","line":202,"in_reply_to":"9f560f44_ce4d8cc6","updated":"2020-09-18 06:49:51.000000000","message":"Done","commit_id":"e7c86ed52e530e276a8a2d1bfe7c1f975214dd31"},{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"05a1422b434dd2570fa3512f8b0112b2fe907c6d","unresolved":false,"context_lines":[{"line_number":202,"context_line":"                              reporter.name, duration)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    self.sched.statsd.timing("},{"line_number":206,"context_line":"                        \"zuul.reporter.{reporter}.duration\""},{"line_number":207,"context_line":"                        .format(reporter\u003dreporter.name), duration)"},{"line_number":208,"context_line":"                    self.sched.statsd.incr("}],"source_content_type":"text/x-python","patch_set":6,"id":"9f560f44_4e621c3f","line":205,"updated":"2020-09-18 06:01:00.000000000","message":"With disabled statsd reporting self.sched.statsd is None so we need to guard for that. Further stats reporting should not lead to failed reports so we need to catch exceptions there separately, see also https://opendev.org/zuul/zuul/src/branch/master/zuul/connection/__init__.py#L51","commit_id":"e7c86ed52e530e276a8a2d1bfe7c1f975214dd31"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"694e59c242b03a7462f747678a6b06c342837f95","unresolved":false,"context_lines":[{"line_number":202,"context_line":"                              reporter.name, duration)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    self.sched.statsd.timing("},{"line_number":206,"context_line":"                        \"zuul.reporter.{reporter}.duration\""},{"line_number":207,"context_line":"                        .format(reporter\u003dreporter.name), duration)"},{"line_number":208,"context_line":"                    self.sched.statsd.incr("}],"source_content_type":"text/x-python","patch_set":6,"id":"9f560f44_890f0edf","line":205,"in_reply_to":"9f560f44_4e621c3f","updated":"2020-09-18 06:49:51.000000000","message":"Done","commit_id":"e7c86ed52e530e276a8a2d1bfe7c1f975214dd31"},{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"f0d6734da9b7d42858072833b3bb46c96077f8ad","unresolved":false,"context_lines":[{"line_number":202,"context_line":"                              reporter.name, duration_ms)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    if self.sched.statsd:  # only if statsd is enabled"},{"line_number":206,"context_line":"                        self.sched.statsd.timing("},{"line_number":207,"context_line":"                            \"zuul.reporter.{reporter}.duration\""},{"line_number":208,"context_line":"                            .format(reporter\u003dreporter.name), duration_ms)"},{"line_number":209,"context_line":"                        self.sched.statsd.incr("},{"line_number":210,"context_line":"                            \"zuul.reporter.{reporter}.count\""},{"line_number":211,"context_line":"                            .format(reporter\u003dreporter.name))"},{"line_number":212,"context_line":"                except Exception as e:"},{"line_number":213,"context_line":"                    item.setReportedResult(\u0027ERROR\u0027)"},{"line_number":214,"context_line":"                    log.exception(\"Exception while reporting\")"}],"source_content_type":"text/x-python","patch_set":7,"id":"9f560f44_89838ecb","line":211,"range":{"start_line":205,"start_character":0,"end_line":211,"end_character":60},"updated":"2020-09-18 07:13:26.000000000","message":"We still need to catch and log exceptions here since this stats reporting errors must not mark the report as failed.","commit_id":"19528d5297171227b11c8f91dedd3e0ead353b20"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"a77f7f4e3bd9e2d720b110beabafe07c4abb93f4","unresolved":false,"context_lines":[{"line_number":202,"context_line":"                              reporter.name, duration_ms)"},{"line_number":203,"context_line":"                    if ret:"},{"line_number":204,"context_line":"                        report_errors.append(ret)"},{"line_number":205,"context_line":"                    if self.sched.statsd:  # only if statsd is enabled"},{"line_number":206,"context_line":"                        self.sched.statsd.timing("},{"line_number":207,"context_line":"                            \"zuul.reporter.{reporter}.duration\""},{"line_number":208,"context_line":"                            .format(reporter\u003dreporter.name), duration_ms)"},{"line_number":209,"context_line":"                        self.sched.statsd.incr("},{"line_number":210,"context_line":"                            \"zuul.reporter.{reporter}.count\""},{"line_number":211,"context_line":"                            .format(reporter\u003dreporter.name))"},{"line_number":212,"context_line":"                except Exception as e:"},{"line_number":213,"context_line":"                    item.setReportedResult(\u0027ERROR\u0027)"},{"line_number":214,"context_line":"                    log.exception(\"Exception while reporting\")"}],"source_content_type":"text/x-python","patch_set":7,"id":"9f560f44_de8ff572","line":211,"range":{"start_line":205,"start_character":0,"end_line":211,"end_character":60},"in_reply_to":"9f560f44_89838ecb","updated":"2020-09-18 10:47:02.000000000","message":"Done","commit_id":"19528d5297171227b11c8f91dedd3e0ead353b20"},{"author":{"_account_id":7118,"name":"Ian Wienand","email":"iwienand@redhat.com","username":"iwienand"},"change_message_id":"85e5195057b445b210da11f2fe26648250aed296","unresolved":false,"context_lines":[{"line_number":193,"context_line":"        report_errors \u003d []"},{"line_number":194,"context_line":"        if len(action_reporters) \u003e 0:"},{"line_number":195,"context_line":"            for reporter in action_reporters:"},{"line_number":196,"context_line":"                log.debug(\"Reporting to %s started\", reporter.name)"},{"line_number":197,"context_line":"                start \u003d time.monotonic()"},{"line_number":198,"context_line":""},{"line_number":199,"context_line":"                try:"}],"source_content_type":"text/x-python","patch_set":8,"id":"9f560f44_92ccbc34","line":196,"range":{"start_line":196,"start_character":16,"end_line":196,"end_character":67},"updated":"2020-09-28 00:17:22.000000000","message":"Is this really necessary?  Doesn\u0027t seem to have much useful context and will be in the logs a lot?","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"},{"author":{"_account_id":7118,"name":"Ian Wienand","email":"iwienand@redhat.com","username":"iwienand"},"change_message_id":"93b61e0cac876fb257d809a9bb18979b872819ef","unresolved":false,"context_lines":[{"line_number":193,"context_line":"        report_errors \u003d []"},{"line_number":194,"context_line":"        if len(action_reporters) \u003e 0:"},{"line_number":195,"context_line":"            for reporter in action_reporters:"},{"line_number":196,"context_line":"                log.debug(\"Reporting to %s started\", reporter.name)"},{"line_number":197,"context_line":"                start \u003d time.monotonic()"},{"line_number":198,"context_line":""},{"line_number":199,"context_line":"                try:"}],"source_content_type":"text/x-python","patch_set":8,"id":"9f560f44_237c75b5","line":196,"range":{"start_line":196,"start_character":16,"end_line":196,"end_character":67},"in_reply_to":"9f560f44_3f9494e7","updated":"2020-09-28 22:22:34.000000000","message":"ok, i guess if it\u0027s a result of debugging some real thing then it\u0027s useful enough","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"fe3d08f292c567f40d3fc0b0adfdc039f82d5312","unresolved":false,"context_lines":[{"line_number":193,"context_line":"        report_errors \u003d []"},{"line_number":194,"context_line":"        if len(action_reporters) \u003e 0:"},{"line_number":195,"context_line":"            for reporter in action_reporters:"},{"line_number":196,"context_line":"                log.debug(\"Reporting to %s started\", reporter.name)"},{"line_number":197,"context_line":"                start \u003d time.monotonic()"},{"line_number":198,"context_line":""},{"line_number":199,"context_line":"                try:"}],"source_content_type":"text/x-python","patch_set":8,"id":"9f560f44_3f9494e7","line":196,"range":{"start_line":196,"start_character":16,"end_line":196,"end_character":67},"in_reply_to":"9f560f44_92ccbc34","updated":"2020-09-28 10:20:47.000000000","message":"Yes, we wanted to have both, logs and stats. Since it is \"debug\" it can be turned off. The logging here enables us to detect if a concrete problem with an event was due to a reporter and which one. The stats do not contain such information. Is it a blocker for you?","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"},{"author":{"_account_id":7118,"name":"Ian Wienand","email":"iwienand@redhat.com","username":"iwienand"},"change_message_id":"85e5195057b445b210da11f2fe26648250aed296","unresolved":false,"context_lines":[{"line_number":206,"context_line":"                    report_errors.append(str(e))"},{"line_number":207,"context_line":""},{"line_number":208,"context_line":"                duration_ms \u003d int((time.monotonic() - start) * 1000)"},{"line_number":209,"context_line":"                log.debug(\"Reporting to %s finished in %sms\","},{"line_number":210,"context_line":"                          reporter.name, duration_ms)"},{"line_number":211,"context_line":"                if self.sched.statsd:  # only if statsd is enabled"},{"line_number":212,"context_line":"                    try:"},{"line_number":213,"context_line":"                        self.sched.statsd.timing("}],"source_content_type":"text/x-python","patch_set":8,"id":"9f560f44_128eeccf","line":210,"range":{"start_line":209,"start_character":5,"end_line":210,"end_character":53},"updated":"2020-09-28 00:17:22.000000000","message":"This also -- we\u0027re logging it in the stat","commit_id":"eb73728823ebef8a4f7209dade0ca245ea563d29"},{"author":{"_account_id":4146,"name":"Clark Boylan","email":"cboylan@sapwetik.org","username":"cboylan"},"change_message_id":"351db17854aaebe8020ddbbdd966be51abb2cc1d","unresolved":false,"context_lines":[{"line_number":1217,"context_line":"            self.pipeline._consecutive_failures \u003e\u003d self.pipeline.disable_at):"},{"line_number":1218,"context_line":"            self.pipeline._disabled \u003d True"},{"line_number":1219,"context_line":"        if actions:"},{"line_number":1220,"context_line":"            log.info(\"Reporting item %s, actions: %s\", item, actions)"},{"line_number":1221,"context_line":"            ret \u003d self.sendReport(actions, item)"},{"line_number":1222,"context_line":"            if ret:"},{"line_number":1223,"context_line":"                log.error(\"Reporting item %s received: %s\", item, ret)"}],"source_content_type":"text/x-python","patch_set":9,"id":"9f560f44_6315cd4c","line":1220,"updated":"2020-09-28 22:29:16.000000000","message":"To alleviate ianw\u0027s concern with logging maybe we can drop this log.info then in sendReport() record what is logged here. Then add in a second logger at debug log level that records the time taken? That way this line and \"log.debug(\"Reporting to %s started\", reporter.name)\" aren\u0027t redundant?\n\nSomething like:\n\n  log.info(\"Reporting item %s, actions: %s, to %s\", item, actions, reporter.name)\n  # Run reporter actions\n  log.debug(\"Reporting %s to %s finished in %sms\", item, reporter.name, duration_ms)\n\nIn sendReport()?","commit_id":"69b3b02870d50b7c20e472f68b5effb5e82b59e9"},{"author":{"_account_id":30637,"name":"Jan Kubovy","email":"jan.kubovy@bmw.de","username":"kubovy"},"change_message_id":"a6f834409042fb4fab090e73428d5d0197b3e601","unresolved":false,"context_lines":[{"line_number":1217,"context_line":"            self.pipeline._consecutive_failures \u003e\u003d self.pipeline.disable_at):"},{"line_number":1218,"context_line":"            self.pipeline._disabled \u003d True"},{"line_number":1219,"context_line":"        if actions:"},{"line_number":1220,"context_line":"            log.info(\"Reporting item %s, actions: %s\", item, actions)"},{"line_number":1221,"context_line":"            ret \u003d self.sendReport(actions, item)"},{"line_number":1222,"context_line":"            if ret:"},{"line_number":1223,"context_line":"                log.error(\"Reporting item %s received: %s\", item, ret)"}],"source_content_type":"text/x-python","patch_set":9,"id":"9f560f44_3215d43e","line":1220,"in_reply_to":"9f560f44_03005102","updated":"2020-09-29 13:18:14.000000000","message":"Yes, we needed to also see the start. This log could be IMHO removed or downgraded to debug.","commit_id":"69b3b02870d50b7c20e472f68b5effb5e82b59e9"},{"author":{"_account_id":16068,"name":"Tobias Henkel","email":"tobias.henkel@bmw.de","username":"tobias.henkel"},"change_message_id":"a2f9e4270d87a841d5b46a3a125d745ee36ab7c0","unresolved":true,"context_lines":[{"line_number":1217,"context_line":"            self.pipeline._consecutive_failures \u003e\u003d self.pipeline.disable_at):"},{"line_number":1218,"context_line":"            self.pipeline._disabled \u003d True"},{"line_number":1219,"context_line":"        if actions:"},{"line_number":1220,"context_line":"            log.info(\"Reporting item %s, actions: %s\", item, actions)"},{"line_number":1221,"context_line":"            ret \u003d self.sendReport(actions, item)"},{"line_number":1222,"context_line":"            if ret:"},{"line_number":1223,"context_line":"                log.error(\"Reporting item %s received: %s\", item, ret)"}],"source_content_type":"text/x-python","patch_set":9,"id":"ca7c7886_5288c171","line":1220,"in_reply_to":"9f560f44_3215d43e","updated":"2020-12-02 12:13:18.000000000","message":"I think we can drop the started log. If it blocks indefinitely zuul is blocked completely and a thread dump can reveal where it\u0027s blocked anyway (which is easier than spotting the last started message in a giant log).","commit_id":"69b3b02870d50b7c20e472f68b5effb5e82b59e9"},{"author":{"_account_id":7118,"name":"Ian Wienand","email":"iwienand@redhat.com","username":"iwienand"},"change_message_id":"663ae1e204cd0a6c819a14fc5d8574378520fbc1","unresolved":false,"context_lines":[{"line_number":1217,"context_line":"            self.pipeline._consecutive_failures \u003e\u003d self.pipeline.disable_at):"},{"line_number":1218,"context_line":"            self.pipeline._disabled \u003d True"},{"line_number":1219,"context_line":"        if actions:"},{"line_number":1220,"context_line":"            log.info(\"Reporting item %s, actions: %s\", item, actions)"},{"line_number":1221,"context_line":"            ret \u003d self.sendReport(actions, item)"},{"line_number":1222,"context_line":"            if ret:"},{"line_number":1223,"context_line":"                log.error(\"Reporting item %s received: %s\", item, ret)"}],"source_content_type":"text/x-python","patch_set":9,"id":"9f560f44_03005102","line":1220,"in_reply_to":"9f560f44_6315cd4c","updated":"2020-09-28 22:33:18.000000000","message":"I guess the issue is if it never came back, you didn\u0027t see that it even started (i.e. the database just ate requests or something?)  I guess it depends what inspired this.\n\nBut I support less debug messages, if appropriate.","commit_id":"69b3b02870d50b7c20e472f68b5effb5e82b59e9"}]}