Skip to content

Log all diskcache state changes and stream access

Paul Okstad (ex-GitLab) requested to merge po-diskcache-log-state into master

This adds an additional log message that will improve visibility of whether the diskcache is serving stale data or not. The "freshness" of the cache is determined by the repo's cache state file. The contents of this file will now be logged whenever it is updated.

Additionally, the path of the cached response on disk will be logged each time the diskcache is used. This can be used to help determine if stale data is being served after the cache is expected to be invalid. Each time the state file changes, we expect a new request file path.

Sample logs from GDK:

2019-12-11_21:23:40.47252 praefect-gitaly-0     : time="2019-12-11T13:23:40-08:00" level=info msg="diskcache state change" correlation_id=3Yl6Y0iGpN5 diskcache=d7cdb7f9-931a-4c96-9ac2-0e6bc27ded15 grpc.meta.auth_version=v1 grpc.method=InfoRefsUploadPack grpc.request.fullMethod=/gitaly.SmartHTTPService/InfoRefsUploadPack grpc.request.glProjectPath=flightjs/flight grpc.request.glRepository=project-6 grpc.request.repoPath=@hashed/e7/f6/e7f6c011776e8db7cd330b54174fd76f7d0216b612387a5ffcfb81e6f0919683.git grpc.request.repoStorage=praefect-internal-0 grpc.request.topLevelGroup=@hashed grpc.service=gitaly.SmartHTTPService grpc.start_time="2019-12-11T13:23:40-08:00" peer.address= pid=69616 span.kind=server system=grpc
2019-12-11_21:23:40.47257 praefect-gitaly-0     : time="2019-12-11T13:23:40-08:00" level=info msg="getting stream" correlation_id=3Yl6Y0iGpN5 grpc.meta.auth_version=v1 grpc.method=InfoRefsUploadPack grpc.request.fullMethod=/gitaly.SmartHTTPService/InfoRefsUploadPack grpc.request.glProjectPath=flightjs/flight grpc.request.glRepository=project-6 grpc.request.repoPath=@hashed/e7/f6/e7f6c011776e8db7cd330b54174fd76f7d0216b612387a5ffcfb81e6f0919683.git grpc.request.repoStorage=praefect-internal-0 grpc.request.topLevelGroup=@hashed grpc.service=gitaly.SmartHTTPService grpc.start_time="2019-12-11T13:23:40-08:00" peer.address= pid=69616 span.kind=server stream_path=/Users/paulokstad/gdk/repositories/+gitaly/cache/09/75ee174a90b279b5e9e8fea9c9edeaf3625e1f86b233ce592a1db5bb6a4f75 system=grpc
2019-12-11_21:23:40.47263 praefect-gitaly-0     : time="2019-12-11T13:23:40-08:00" level=info msg="cache miss for UploadPack response" correlation_id=3Yl6Y0iGpN5 grpc.meta.auth_version=v1 grpc.method=InfoRefsUploadPack grpc.request.fullMethod=/gitaly.SmartHTTPService/InfoRefsUploadPack grpc.request.glProjectPath=flightjs/flight grpc.request.glRepository=project-6 grpc.request.repoPath=@hashed/e7/f6/e7f6c011776e8db7cd330b54174fd76f7d0216b612387a5ffcfb81e6f0919683.git grpc.request.repoStorage=praefect-internal-0 grpc.request.topLevelGroup=@hashed grpc.service=gitaly.SmartHTTPService grpc.start_time="2019-12-11T13:23:40-08:00" peer.address= pid=69616 service=upload-pack span.kind=server system=grpc
2019-12-11_21:23:40.47411 praefect-gitaly-0     : time="2019-12-11T13:23:40-08:00" level=info msg="putting stream" correlation_id=3Yl6Y0iGpN5 grpc.meta.auth_version=v1 grpc.method=InfoRefsUploadPack grpc.request.fullMethod=/gitaly.SmartHTTPService/InfoRefsUploadPack grpc.request.glProjectPath=flightjs/flight grpc.request.glRepository=project-6 grpc.request.repoPath=@hashed/e7/f6/e7f6c011776e8db7cd330b54174fd76f7d0216b612387a5ffcfb81e6f0919683.git grpc.request.repoStorage=praefect-internal-0 grpc.request.topLevelGroup=@hashed grpc.service=gitaly.SmartHTTPService grpc.start_time="2019-12-11T13:23:40-08:00" peer.address= pid=69616 span.kind=server stream_path=/Users/paulokstad/gdk/repositories/+gitaly/cache/09/75ee174a90b279b5e9e8fea9c9edeaf3625e1f86b233ce592a1db5bb6a4f75 system=grpc
2019-12-11_21:23:40.50958 praefect-gitaly-0     : time="2019-12-11T13:23:40-08:00" level=info msg="finished streaming call with code OK" correlation_id=3Yl6Y0iGpN5 grpc.code=OK grpc.meta.auth_version=v1 grpc.method=InfoRefsUploadPack grpc.request.fullMethod=/gitaly.SmartHTTPService/InfoRefsUploadPack grpc.request.glProjectPath=flightjs/flight grpc.request.glRepository=project-6 grpc.request.repoPath=@hashed/e7/f6/e7f6c011776e8db7cd330b54174fd76f7d0216b612387a5ffcfb81e6f0919683.git grpc.request.repoStorage=praefect-internal-0 grpc.request.topLevelGroup=@hashed grpc.service=gitaly.SmartHTTPService grpc.start_time="2019-12-11T13:23:40-08:00" grpc.time_ms=62.286 peer.address= pid=69616 span.kind=server system=grpc

Assists the investigation of #2221 (comment 256324954)

Edited by GitLab Release Tools Bot

Merge request reports