Logs are extremely verbose in 2.1.17 #878
Description
Problem Description
After upgrading to 2.1.17 from 2.1.16, our log verbosity has increased dramatically, with no change to the configured log level.
What is actually happening
With version 2.1.16 our average log lines per event (after parsing with jq) was about 35 lines. After upgrading to 2.1.17 each event is now ~800 lines, an increase of roughly 2,285%.
After noticing this, we've tried decreasing the log level to info but it made no difference.
How can we reduce the verbosity of these logs?
What is the expected behavior
- a patch upgrade should not change behavior so dramatically, and
- changing the log level should result in a different level of logging
example log event with 2.1.16:
{
"level": 30,
"time": 1756832405267,
"pid": 25,
"hostname": "safe-settings-77b77469d8-4ts2n",
"name": "http",
"req": {
"id": "38c3c86b-e3b2-455c-8a54-9fbe9f9ada19",
"method": "GET",
"url": "/",
"query": {},
"params": {},
"headers": {
"host": "10.x.x.x:31280",
"connection": "close",
"user-agent": "ELB-HealthChecker/2.0",
"accept-encoding": "gzip, compressed"
},
"remoteAddress": "::ffff:10.x.x.x",
"remotePort": 57629
},
"res": {
"statusCode": 302,
"headers": {
"x-powered-by": "Express",
"location": "/probot",
"vary": "Accept",
"content-type": "text/plain; charset=utf-8",
"content-length": "29"
}
},
"responseTime": 0,
"msg": "GET / 302 - 0ms"
}
example log event with 2.1.17:
{
"level": 30,
"time": 1758640712508,
"pid": 25,
"hostname": "safe-settings-756484dfc-5qm8g",
"name": "probot",
"req": {
"_consuming": false,
"_dumped": false,
"_events": {},
"_parsedUrl": {
"_raw": "/",
"auth": null,
"hash": null,
"host": null,
"hostname": null,
"href": "/",
"path": "/",
"pathname": "/",
"port": null,
"protocol": null,
"query": null,
"search": null,
"slashes": null
},
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"aborted": false,
"baseUrl": "",
"client": {
"_closeAfterHandlingError": false,
"_events": {
"close": [
null,
null
],
"end": [
null,
null
]
},
"_eventsCount": 8,
"_hadError": false,
"_host": null,
"_httpMessage": {
"_closed": false,
"_contentLength": null,
"_defaultKeepAlive": true,
"_events": {},
"_eventsCount": 1,
"_expect_continue": false,
"_hasBody": true,
"_header": null,
"_headerSent": false,
"_keepAliveTimeout": 5000,
"_last": false,
"_maxRequestsPerSocket": 0,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_sent100": false,
"_trailer": "",
"chunkedEncoding": false,
"destroyed": false,
"finished": false,
"locals": {},
"maxRequestsOnConnectionReached": false,
"outputData": [],
"outputSize": 0,
"req": "[Circular]",
"sendDate": true,
"shouldKeepAlive": false,
"socket": "[Circular]",
"strictContentLength": false,
"useChunkedEncodingByDefault": true,
"writable": true
},
"_parent": null,
"_paused": false,
"_pendingData": null,
"_pendingEncoding": "",
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"_server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
},
"_sockname": null,
"_writableState": {
"bufferedIndex": 0,
"corked": 0,
"highWaterMark": 16384,
"length": 0,
"pendingcb": 0,
"writelen": 0
},
"allowHalfOpen": true,
"connecting": false,
"parser": {
"0": null,
"_consumed": true,
"_headers": [],
"_url": "",
"incoming": "[Circular]",
"joinDuplicateHeaders": null,
"maxHeaderPairs": 2000,
"outgoing": null,
"socket": "[Circular]"
},
"server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
}
},
"complete": false,
"httpVersion": "1.1",
"httpVersionMajor": 1,
"httpVersionMinor": 1,
"id": "d9f1cda2-ab66-4af8-a5ad-e80f3e2e0776",
"joinDuplicateHeaders": null,
"method": "GET",
"originalUrl": "/",
"params": {},
"query": {},
"rawHeaders": [
"Host",
"10.x.x.x:30962",
"Connection",
"close",
"User-Agent",
"ELB-HealthChecker/2.0",
"Accept-Encoding",
"gzip, compressed"
],
"rawTrailers": [],
"res": {
"_closed": false,
"_contentLength": null,
"_defaultKeepAlive": true,
"_events": {},
"_eventsCount": 1,
"_expect_continue": false,
"_hasBody": true,
"_header": null,
"_headerSent": false,
"_keepAliveTimeout": 5000,
"_last": false,
"_maxRequestsPerSocket": 0,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_sent100": false,
"_trailer": "",
"chunkedEncoding": false,
"destroyed": false,
"finished": false,
"locals": {},
"maxRequestsOnConnectionReached": false,
"outputData": [],
"outputSize": 0,
"req": "[Circular]",
"sendDate": true,
"shouldKeepAlive": false,
"socket": {
"_closeAfterHandlingError": false,
"_events": {
"close": [
null,
null
],
"end": [
null,
null
]
},
"_eventsCount": 8,
"_hadError": false,
"_host": null,
"_httpMessage": "[Circular]",
"_parent": null,
"_paused": false,
"_pendingData": null,
"_pendingEncoding": "",
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"_server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
},
"_sockname": null,
"_writableState": {
"bufferedIndex": 0,
"corked": 0,
"highWaterMark": 16384,
"length": 0,
"pendingcb": 0,
"writelen": 0
},
"allowHalfOpen": true,
"connecting": false,
"parser": {
"0": null,
"_consumed": true,
"_headers": [],
"_url": "",
"incoming": "[Circular]",
"joinDuplicateHeaders": null,
"maxHeaderPairs": 2000,
"outgoing": null,
"socket": "[Circular]"
},
"server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
}
},
"strictContentLength": false,
"useChunkedEncodingByDefault": true,
"writable": true
},
"socket": {
"_closeAfterHandlingError": false,
"_events": {
"close": [
null,
null
],
"end": [
null,
null
]
},
"_eventsCount": 8,
"_hadError": false,
"_host": null,
"_httpMessage": {
"_closed": false,
"_contentLength": null,
"_defaultKeepAlive": true,
"_events": {},
"_eventsCount": 1,
"_expect_continue": false,
"_hasBody": true,
"_header": null,
"_headerSent": false,
"_keepAliveTimeout": 5000,
"_last": false,
"_maxRequestsPerSocket": 0,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_sent100": false,
"_trailer": "",
"chunkedEncoding": false,
"destroyed": false,
"finished": false,
"locals": {},
"maxRequestsOnConnectionReached": false,
"outputData": [],
"outputSize": 0,
"req": "[Circular]",
"sendDate": true,
"shouldKeepAlive": false,
"socket": "[Circular]",
"strictContentLength": false,
"useChunkedEncodingByDefault": true,
"writable": true
},
"_parent": null,
"_paused": false,
"_pendingData": null,
"_pendingEncoding": "",
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"_server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
},
"_sockname": null,
"_writableState": {
"bufferedIndex": 0,
"corked": 0,
"highWaterMark": 16384,
"length": 0,
"pendingcb": 0,
"writelen": 0
},
"allowHalfOpen": true,
"connecting": false,
"parser": {
"0": null,
"_consumed": true,
"_headers": [],
"_url": "",
"incoming": "[Circular]",
"joinDuplicateHeaders": null,
"maxHeaderPairs": 2000,
"outgoing": null,
"socket": "[Circular]"
},
"server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
}
},
"statusCode": null,
"statusMessage": null,
"upgrade": false,
"url": "/"
},
"res": {
"_closed": false,
"_contentLength": "29",
"_defaultKeepAlive": true,
"_events": {},
"_eventsCount": 1,
"_expect_continue": false,
"_hasBody": true,
"_header": "HTTP/1.1 302 Found\r\nX-Powered-By: Express\r\nLocation: /probot\r\nVary: Accept\r\nContent-Type: text/plain; charset=utf-8\r\nContent-Length: 29\r\nDate: Tue, 23 Sep 2025 15:18:32 GMT\r\nConnection: close\r\n\r\n",
"_headerSent": true,
"_keepAliveTimeout": 5000,
"_last": true,
"_maxRequestsPerSocket": 0,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_sent100": false,
"_trailer": "",
"allLogs": [
{}
],
"chunkedEncoding": false,
"destroyed": false,
"finished": true,
"locals": {},
"log": {},
"maxRequestsOnConnectionReached": false,
"outputData": [],
"outputSize": 0,
"req": {
"_consuming": false,
"_dumped": true,
"_events": {},
"_eventsCount": 1,
"_parsedUrl": {
"_raw": "/",
"auth": null,
"hash": null,
"host": null,
"hostname": null,
"href": "/",
"path": "/",
"pathname": "/",
"port": null,
"protocol": null,
"query": null,
"search": null,
"slashes": null
},
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"aborted": false,
"allLogs": [
{}
],
"baseUrl": "",
"client": {
"_closeAfterHandlingError": false,
"_events": {
"end": [
null,
null
]
},
"_eventsCount": 9,
"_hadError": false,
"_host": null,
"_httpMessage": null,
"_parent": null,
"_paused": false,
"_pendingData": null,
"_pendingEncoding": "",
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"_server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
},
"_sockname": null,
"_writableState": {
"bufferedIndex": 0,
"corked": 0,
"highWaterMark": 16384,
"length": 0,
"pendingcb": 1,
"writelen": 0
},
"allowHalfOpen": true,
"connecting": false,
"parser": {
"0": null,
"_consumed": true,
"_headers": [],
"_url": "",
"incoming": "[Circular]",
"joinDuplicateHeaders": null,
"maxHeaderPairs": 2000,
"outgoing": null,
"socket": "[Circular]"
},
"server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
}
},
"complete": true,
"httpVersion": "1.1",
"httpVersionMajor": 1,
"httpVersionMinor": 1,
"id": "d9f1cda2-ab66-4af8-a5ad-e80f3e2e0776",
"joinDuplicateHeaders": null,
"log": {},
"method": "GET",
"originalUrl": "/",
"params": {},
"query": {},
"rawHeaders": [
"Host",
"10.x.x.x:30962",
"Connection",
"close",
"User-Agent",
"ELB-HealthChecker/2.0",
"Accept-Encoding",
"gzip, compressed"
],
"rawTrailers": [],
"res": "[Circular]",
"route": {
"methods": {
"get": true
},
"path": "/",
"stack": [
{
"keys": [],
"method": "get",
"name": "<anonymous>",
"regexp": "[Object]"
}
]
},
"socket": {
"_closeAfterHandlingError": false,
"_events": {
"end": [
null,
null
]
},
"_eventsCount": 9,
"_hadError": false,
"_host": null,
"_httpMessage": null,
"_parent": null,
"_paused": false,
"_pendingData": null,
"_pendingEncoding": "",
"_readableState": {
"awaitDrainWriters": null,
"buffer": [],
"bufferIndex": 0,
"highWaterMark": 16384,
"length": 0,
"pipes": []
},
"_server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
},
"_sockname": null,
"_writableState": {
"bufferedIndex": 0,
"corked": 0,
"highWaterMark": 16384,
"length": 0,
"pendingcb": 1,
"writelen": 0
},
"allowHalfOpen": true,
"connecting": false,
"parser": {
"0": null,
"_consumed": true,
"_headers": [],
"_url": "",
"incoming": "[Circular]",
"joinDuplicateHeaders": null,
"maxHeaderPairs": 2000,
"outgoing": null,
"socket": "[Circular]"
},
"server": {
"_connectionKey": "6::::3000",
"_connections": 1,
"_events": {},
"_eventsCount": 4,
"_handle": {
"reading": false
},
"_listeningId": 2,
"_unref": false,
"_usingWorkers": false,
"_workers": [],
"allowHalfOpen": true,
"connectionsCheckingInterval": 30000,
"headersTimeout": 60000,
"highWaterMark": 16384,
"httpAllowHalfOpen": false,
"keepAlive": false,
"keepAliveInitialDelay": 0,
"keepAliveTimeout": 5000,
"maxHeadersCount": null,
"maxRequestsPerSocket": 0,
"noDelay": true,
"pauseOnConnect": false,
"rejectNonStandardBodyWrites": false,
"requestTimeout": 300000,
"requireHostHeader": true,
"timeout": 0
}
},
"statusCode": null,
"statusMessage": null,
"upgrade": false,
"url": "/"
},
"sendDate": true,
"shouldKeepAlive": false,
"socket": null,
"statusCode": 302,
"statusMessage": "Found",
"strictContentLength": false,
"useChunkedEncodingByDefault": true,
"writable": true
},
"responseTime": 0,
"msg": "GET / 302 - 0ms"
}
Context
Are you using the hosted instance of probot/settings or running your own?
self-hosted
If running your own instance, are you using it with github.com or GitHub Enterprise?
github.com