Skip to content

Commit fe2c158

Browse files
committed
feat(messagequeue): level the queue's own logs separately
## Summary ### Why? The services run at debug, and the queue logs a line per message published, fetched, leased and acked. Reading a service's logs means scrolling past hundreds of `fetched messages {"count": 0}` to find the one line that matters — following a request through the pipeline is impractical at the level everything else is useful at. Turning the whole service down to info loses the output that is actually being read. The queue's chatter is the part worth silencing, not the service's. ### What? `Params.LogLevel` sets the minimum level for the queue's own logs, applied with `zap.IncreaseLevel` so the rest of the service keeps the level it was built with. Empty selects info, which is what stops the chatter by default. The four servers pass `QUEUE_LOG_LEVEL` through, and the compose files forward it, so the queue can be turned back up for a run that is chasing a message that never arrived: ``` QUEUE_LOG_LEVEL=debug make local-submitqueue-start ``` The level is a raw string on `Params`, parsed in the package, which keeps the environment lookup in the wiring layer where the other knobs live. `IncreaseLevel` can only raise the level, never lower it, so this cannot be used to make a quiet service verbose — an unparseable value is rejected at construction rather than silently ignored. ## Test Plan ✅ `bazel test //platform/extension/messagequeue/mysql:go_default_test` — the level is accepted, and a value that is not a level fails construction. ✅ `make test` — 98 targets. ✅ Passthrough verified rather than assumed, since compose forwards only what it declares: `QUEUE_LOG_LEVEL=debug docker compose -f service/submitqueue/docker-compose.yml config` shows the variable set on all three services.
1 parent ece32f5 commit fe2c158

13 files changed

Lines changed: 94 additions & 2 deletions

File tree

doc/howto/PROVIDER-E2E.md

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -134,6 +134,14 @@ Runway logs each merge and each head-branch move:
134134
moved change head branch to its landed commit {"change": "you/repo#1", "branch": "refs/heads/feature-a", ...}
135135
```
136136

137+
The message queue logs a line per message published, fetched, leased and acked, which at debug level buries everything else a service says. It is levelled separately from the rest of the service, at info by default. To follow the queue itself — chasing a message that never arrived, or a partition that never got leased — turn it back up for the services you care about:
138+
139+
```bash
140+
QUEUE_LOG_LEVEL=debug make local-submitqueue-start
141+
```
142+
143+
`QUEUE_LOG_LEVEL` takes any zap level name. It can only raise the queue's level above the one the service logger was built with, never lower it, so it cannot be used to make a quiet service verbose.
144+
137145
## When it does not work
138146

139147
**The push is rejected on the first try.** Branch protection on `main` — required status checks, or a linear-history or no-force-push rule — applies to the merger like anyone else. Either relax it on the scratch repo or add the token's identity to the bypass list.

platform/extension/messagequeue/mysql/BUILD.bazel

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ go_library(
2626
"@com_github_uber_go_tally//:go_default_library",
2727
"@org_uber_go_mock//gomock:go_default_library",
2828
"@org_uber_go_zap//:go_default_library",
29+
"@org_uber_go_zap//zapcore:go_default_library",
2930
],
3031
)
3132

platform/extension/messagequeue/mysql/sql.go

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ import (
2222

2323
"github.com/uber-go/tally"
2424
"go.uber.org/zap"
25+
"go.uber.org/zap/zapcore"
2526

2627
extqueue "github.com/uber/submitqueue/platform/extension/messagequeue"
2728
)
@@ -40,6 +41,16 @@ type Params struct {
4041
// Logger for debugging and observability (required)
4142
Logger *zap.Logger
4243

44+
// LogLevel is the minimum level for the queue's own logs, as a zap level
45+
// name ("debug", "info", ...). Empty selects info.
46+
//
47+
// The queue logs a line per message published, fetched, leased and acked,
48+
// which at debug buries everything else a service says. Levelling it here
49+
// rather than at the service logger keeps the rest of that service's debug
50+
// output intact. The level can only be raised above the one the supplied
51+
// logger was built with, never lowered.
52+
LogLevel string
53+
4354
// MetricsScope for metrics collection (required)
4455
MetricsScope tally.Scope
4556

@@ -55,8 +66,17 @@ func NewQueue(params Params) (extqueue.Queue, error) {
5566
return nil, fmt.Errorf("failed to ping database: %w", err)
5667
}
5768

58-
logger := params.Logger.Sugar().Named("queue_mysql")
59-
logger.Infow("created SQL queue")
69+
level := zapcore.InfoLevel
70+
if params.LogLevel != "" {
71+
parsed, err := zapcore.ParseLevel(params.LogLevel)
72+
if err != nil {
73+
return nil, fmt.Errorf("invalid queue log level %q: %w", params.LogLevel, err)
74+
}
75+
level = parsed
76+
}
77+
78+
logger := params.Logger.WithOptions(zap.IncreaseLevel(level)).Sugar().Named("queue_mysql")
79+
logger.Infow("created SQL queue", "log_level", level.String())
6080

6181
// Create stores
6282
messageStore := newMessageStore(params.DB, logger, params.MetricsScope)

platform/extension/messagequeue/mysql/sql_test.go

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,44 @@ func TestNewQueue(t *testing.T) {
7070

7171
require.NoError(t, mock.ExpectationsWereMet())
7272
})
73+
t.Run("accepts a log level", func(t *testing.T) {
74+
db, mock, err := sqlmock.New(sqlmock.MonitorPingsOption(true))
75+
require.NoError(t, err)
76+
defer db.Close()
77+
78+
mock.ExpectPing()
79+
80+
q, err := NewQueue(Params{
81+
DB: db,
82+
Logger: zaptest.NewLogger(t),
83+
LogLevel: "debug",
84+
MetricsScope: tally.NewTestScope("test", nil),
85+
})
86+
87+
require.NoError(t, err)
88+
require.NotNil(t, q)
89+
assert.NoError(t, q.Close())
90+
91+
require.NoError(t, mock.ExpectationsWereMet())
92+
})
93+
94+
t.Run("error when the log level is not a level", func(t *testing.T) {
95+
db, mock, err := sqlmock.New(sqlmock.MonitorPingsOption(true))
96+
require.NoError(t, err)
97+
defer db.Close()
98+
99+
mock.ExpectPing()
100+
101+
q, err := NewQueue(Params{
102+
DB: db,
103+
Logger: zaptest.NewLogger(t),
104+
LogLevel: "loud",
105+
MetricsScope: tally.NewTestScope("test", nil),
106+
})
107+
108+
require.Error(t, err)
109+
assert.Nil(t, q)
110+
})
73111
}
74112

75113
func TestQueue_Publisher(t *testing.T) {

service/runway/server/docker-compose.yml

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,9 @@ services:
4949
- MERGER=${SQ_RUNWAY_MERGER:-}
5050
# Queue infrastructure connection
5151
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
52+
# Level for the queue's own logs; info by default so its per-message
53+
# chatter does not bury the rest of the service at debug.
54+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
5255
- HOSTNAME=runway-dev
5356
depends_on:
5457
mysql-queue:

service/runway/server/main.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,7 @@ func run() error {
138138
mysqlQueue, err := queueMySQL.NewQueue(queueMySQL.Params{
139139
DB: queueDB,
140140
Logger: logger,
141+
LogLevel: os.Getenv("QUEUE_LOG_LEVEL"),
141142
MetricsScope: scope.SubScope("queue"),
142143
})
143144
if err != nil {

service/stovepipe/docker-compose.yml

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,9 @@ services:
6767
- PORT=:8080
6868
- STORAGE_MYSQL_DSN=root:root@tcp(mysql-app:3306)/submitqueue?parseTime=true
6969
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
70+
# Level for the queue's own logs; info by default so its per-message
71+
# chatter does not bury the rest of the service at debug.
72+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
7073
- HOSTNAME=stovepipe-dev
7174
depends_on:
7275
mysql-app:

service/stovepipe/server/main.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -237,6 +237,7 @@ func run() error {
237237
mysqlQueue, err := queueMySQL.NewQueue(queueMySQL.Params{
238238
DB: queueDB,
239239
Logger: logger,
240+
LogLevel: os.Getenv("QUEUE_LOG_LEVEL"),
240241
MetricsScope: scope.SubScope("queue"),
241242
})
242243
if err != nil {

service/submitqueue/docker-compose.yml

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,9 @@ services:
7373
- MYSQL_DSN=root:root@tcp(mysql-app:3306)/submitqueue?parseTime=true
7474
# Queue infrastructure connection (separate database)
7575
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
76+
# Level for the queue's own logs; info by default so its per-message
77+
# chatter does not bury the rest of the service at debug.
78+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
7679
# Path to YAML queue configuration baked into the image
7780
- QUEUE_CONFIG_PATH=/app/queues.yaml
7881
# Stable subscriber name for the request-log consumer
@@ -101,6 +104,9 @@ services:
101104
- MYSQL_DSN=root:root@tcp(mysql-app:3306)/submitqueue?parseTime=true
102105
# Queue infrastructure connection (separate database)
103106
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
107+
# Level for the queue's own logs; info by default so its per-message
108+
# chatter does not bury the rest of the service at debug.
109+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
104110
- HOSTNAME=orchestrator-dev
105111
# Consumer-gate state shared with the host (see header comment)
106112
- CONSUMER_GATE_DIR=/var/submitqueue/consumergate
@@ -129,6 +135,9 @@ services:
129135
- PORT=:8080
130136
# Queue infrastructure connection (shared with the orchestrator)
131137
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
138+
# Level for the queue's own logs; info by default so its per-message
139+
# chatter does not bury the rest of the service at debug.
140+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
132141
- HOSTNAME=runway-dev
133142
# Consumer-gate state shared with the host (see header comment)
134143
- CONSUMER_GATE_DIR=/var/submitqueue/consumergate

service/submitqueue/gateway/server/docker-compose.yml

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,9 @@ services:
6262
- MYSQL_DSN=root:root@tcp(mysql-app:3306)/submitqueue?parseTime=true
6363
# Queue infrastructure connection (separate database)
6464
- QUEUE_MYSQL_DSN=root:root@tcp(mysql-queue:3306)/submitqueue?parseTime=true
65+
# Level for the queue's own logs; info by default so its per-message
66+
# chatter does not bury the rest of the service at debug.
67+
- QUEUE_LOG_LEVEL=${QUEUE_LOG_LEVEL:-}
6568
# Path to YAML queue configuration baked into the image
6669
- QUEUE_CONFIG_PATH=/app/queues.yaml
6770
# Stable subscriber name for the request-log consumer

0 commit comments

Comments
 (0)