Bots service log records not showing up with monitoring enabled
Context
- Expected behaviour: Bots service log records show up with monitoring enabled
- Current behaviour: With these changes, log records from the bots service no longer appear under any configuration with monitoring enabled
- Steps to reproduce: Start a buildgrid server with a monitoring configuration like this one:
server:
- !channel
port: 50051
insecure_mode: true
# credentials:
# tls-server-key: null
# tls-server-cert: null
# tls-client-certs: null
description: |
A single default instance
instances:
- name: ''
description: |
The main server
storages:
- !disk-storage &main-storage
path: /foo/bar/
services:
- !action-cache &main-action
storage: *main-storage
max_cached_refs: 256
allow_updates: true
- !execution
storage: *main-storage
action_cache: *main-action
- !bytestream
storage: *main-storage
monitoring:
enabled: true
endpoint-type: stdout
serialization-format: json
metric-prefix: foo.bar
- Logs: Here are some logs. The first log is from before the changes (commit 13b59ec1), the second is from after the changes (commit 0a37e8b9). In the second log, all of the logRecords from the bots service are missing.
2019-05-21 17:45:02,441:[ buildgrid.server.instance][DEBUG]: Setting up gRPC server with thread-limit=[20]
{
"sequenceNumber": "1",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.449654Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0
}
}{
"sequenceNumber": "2",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.449793Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0
}
}{
"sequenceNumber": "3",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.449820Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "4",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.449949Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "5",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.449998Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s",
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "6",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.450085Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "OK"
}
}
}{
"sequenceNumber": "7",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.450111Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "UNHEALTHY"
}
}
}{
"sequenceNumber": "8",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:02.450131Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s"
}
}
{
"sequenceNumber": "9",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:02.445951Z",
"domain": "buildgrid.server.instance",
"level": "INFO",
"message": "Adding insecure connection on [[::]:50051]"
}
}{
"sequenceNumber": "10",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.454785Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0
}
}{
"sequenceNumber": "11",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.454886Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0
}
}{
"sequenceNumber": "12",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.454910Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "13",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.454970Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "14",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.455Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s",
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "15",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.455044Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "OK"
}
}
}{
"sequenceNumber": "16",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.455065Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "UNHEALTHY"
}
}
}{
"sequenceNumber": "17",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:07.455087Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s"
}
}{
"sequenceNumber": "18",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460300Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0
}
}{
"sequenceNumber": "19",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460397Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0
}
}{
"sequenceNumber": "20",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460423Z",
"domain": "STATE",
"type": "GAUGE",
"name": "clients-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "21",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460488Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "22",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460522Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s",
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "23",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460573Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "OK"
}
}
}{
"sequenceNumber": "24",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460606Z",
"domain": "STATE",
"type": "GAUGE",
"name": "bots-count",
"value": 0,
"metadata": {
"bot-status": "UNHEALTHY"
}
}
}{
"sequenceNumber": "25",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:12.460662Z",
"domain": "STATE",
"type": "TIMER",
"name": "average-queue-time",
"duration": "0s"
}
}{
"sequenceNumber": "26",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:14.258355Z",
"domain": "buildgrid.server.bots.service",
"level": "DEBUG",
"message": "CreateBotSession request from [ipv6:[::1]:57550]"
}
}{
"sequenceNumber": "27",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:14.259087Z",
"domain": "buildgrid.server.bots.instance",
"level": "INFO",
"message": "Opened session name=[/f28c2694-d6e3-4396-8daf-acd2e6e9d048] for bot=[None.ip-1-74-218-25.dob1.bcpc.bloomberg.com], leases=[]"
}
}{
"sequenceNumber": "28",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:14.765800Z",
"domain": "buildgrid.server.bots.service",
"level": "DEBUG",
"message": "UpdateBotSession request from [ipv6:[::1]:57550]"
}
}{
"sequenceNumber": "29",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:14.766146Z",
"domain": "buildgrid.server.bots.instance",
"level": "DEBUG",
"message": "Sending session update, name=[/f28c2694-d6e3-4396-8daf-acd2e6e9d048], for bot=[None.ip-1-74-218-25.dob1.bcpc.bloomberg.com], leases=[]"
}
}{
"sequenceNumber": "30",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:15.270515Z",
"domain": "buildgrid.server.bots.service",
"level": "DEBUG",
"message": "UpdateBotSession request from [ipv6:[::1]:57550]"
}
}{
"sequenceNumber": "31",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:15.270883Z",
"domain": "buildgrid.server.bots.instance",
"level": "DEBUG",
"message": "Sending session update, name=[/f28c2694-d6e3-4396-8daf-acd2e6e9d048], for bot=[None.ip-1-74-218-25.dob1.bcpc.bloomberg.com], leases=[]"
}
}^C{
"sequenceNumber": "32",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:15.776564Z",
"domain": "buildgrid.server.bots.service",
"level": "DEBUG",
"message": "UpdateBotSession request from [ipv6:[::1]:57550]"
}
}{
"sequenceNumber": "33",
"logRecord": {
"creationTimestamp": "2019-05-21T17:45:15.776898Z",
"domain": "buildgrid.server.bots.instance",
"level": "DEBUG",
"message": "Sending session update, name=[/f28c2694-d6e3-4396-8daf-acd2e6e9d048], for bot=[None.ip-1-74-218-25.dob1.bcpc.bloomberg.com], leases=[]"
}
}
2019-05-21 17:45:26,035:[ buildgrid.server.instance][DEBUG]: Setting up gRPC server with thread-limit=[20]
{
"sequenceNumber": "1",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043479Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.clients-count",
"value": 0
}
}{
"sequenceNumber": "2",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043661Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.bots-count",
"value": 0
}
}{
"sequenceNumber": "3",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043692Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.instance.clients-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "4",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043810Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.instance.bots-count",
"value": 0,
"metadata": {
"instance-name": ""
}
}
}^C{
"sequenceNumber": "5",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043846Z",
"domain": "STATE",
"type": "TIMER",
"name": "foo.bar.instance.average-queue-time",
"duration": "0s",
"metadata": {
"instance-name": ""
}
}
}{
"sequenceNumber": "6",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043906Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.bots-count",
"value": 0,
"metadata": {
"bot-status": "OK"
}
}
}{
"sequenceNumber": "7",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043945Z",
"domain": "STATE",
"type": "GAUGE",
"name": "foo.bar.bots-count",
"value": 0,
"metadata": {
"bot-status": "UNHEALTHY"
}
}
}{
"sequenceNumber": "8",
"metricRecord": {
"creationTimestamp": "2019-05-21T21:45:26.043982Z",
"domain": "STATE",
"type": "TIMER",
"name": "foo.bar.average-queue-time",
"duration": "0s"
}
}
Task Description
The linked changeset should provide some clues here.
Acceptance Criteria
Log records need to appear with monitoring enabled.