Skip to content

Commit 357166a

Browse files
tomerdtomerd
authored
add logging to registry flows (#6266)
motivation: easier debugging changes: * add info logging for actions that may be interesting to users * add debug logging to assist troubleshooting
1 parent a7b3fe1 commit 357166a

File tree

4 files changed

+87
-4
lines changed

4 files changed

+87
-4
lines changed

‎Sources/Basics/AuthorizationProvider.swift

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -225,7 +225,7 @@ public class KeychainAuthorizationProvider: AuthorizationProvider, Authorization
225225
} catch {
226226
switch error {
227227
case AuthorizationProviderError.notFound:
228-
self.observabilityScope.emit(info: "No credentials found for server \(server) in keychain")
228+
self.observabilityScope.emit(debug: "No credentials found for server \(server) in keychain")
229229
case AuthorizationProviderError.other(let detail):
230230
self.observabilityScope.emit(error: detail)
231231
default:

‎Sources/Commands/ToolWorkspaceDelegate.swift

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -178,7 +178,7 @@ class ToolWorkspaceDelegate: WorkspaceDelegate {
178178
// registry signature handlers
179179

180180
func onUnsignedRegistryPackage(registryURL: URL, package: PackageModel.PackageIdentity, version: TSCUtility.Version, completion: (Bool) -> Void) {
181-
self.inputHandler("\(package) @ \(version) from \(registryURL) is unsigned. okay to proceed? (yes/no) ") { response in
181+
self.inputHandler("\(package) \(version) from \(registryURL) is unsigned. okay to proceed? (yes/no) ") { response in
182182
switch response?.lowercased() {
183183
case "yes":
184184
completion(true) // continue
@@ -192,7 +192,7 @@ class ToolWorkspaceDelegate: WorkspaceDelegate {
192192
}
193193

194194
func onUntrustedRegistryPackage(registryURL: URL, package: PackageModel.PackageIdentity, version: TSCUtility.Version, completion: (Bool) -> Void) {
195-
self.inputHandler("\(package) @ \(version) from \(registryURL) is signed with an untrusted certificate. okay to proceed? (yes/no) ") { response in
195+
self.inputHandler("\(package) \(version) from \(registryURL) is signed with an untrusted certificate. okay to proceed? (yes/no) ") { response in
196196
switch response?.lowercased() {
197197
case "yes":
198198
completion(true) // continue

‎Sources/PackageRegistry/RegistryClient.swift

Lines changed: 74 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -129,6 +129,8 @@ public final class RegistryClient: Cancellable {
129129
return completion(.failure(RegistryError.registryNotConfigured(scope: registryIdentity.scope)))
130130
}
131131

132+
observabilityScope.emit(debug: "registry for \(package): \(registry)")
133+
132134
let underlying = {
133135
self._getPackageMetadata(
134136
registry: registry,
@@ -184,9 +186,15 @@ public final class RegistryClient: Cancellable {
184186
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
185187
)
186188

189+
let start = DispatchTime.now()
190+
observabilityScope.emit(info: "retrieving \(package) metadata from \(request.url)")
187191
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
188192
completion(
189193
result.tryMap { response in
194+
observabilityScope
195+
.emit(
196+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
197+
)
190198
switch response.statusCode {
191199
case 200:
192200
let packageMetadata = try response.parseJSON(
@@ -358,9 +366,15 @@ public final class RegistryClient: Cancellable {
358366
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
359367
)
360368

369+
let start = DispatchTime.now()
370+
observabilityScope.emit(info: "retrieving \(package) \(version) metadata from \(request.url)")
361371
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
362372
completion(
363373
result.tryMap { response in
374+
observabilityScope
375+
.emit(
376+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
377+
)
364378
switch response.statusCode {
365379
case 200:
366380
let metadata = try response.parseJSON(
@@ -467,9 +481,15 @@ public final class RegistryClient: Cancellable {
467481
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
468482
)
469483

484+
let start = DispatchTime.now()
485+
observabilityScope.emit(info: "retrieving available manifests for \(package) \(version) from \(request.url)")
470486
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
471487
completion(
472488
result.tryMap { response in
489+
observabilityScope
490+
.emit(
491+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
492+
)
473493
switch response.statusCode {
474494
case 200:
475495
try response.validateAPIVersion()
@@ -601,9 +621,15 @@ public final class RegistryClient: Cancellable {
601621
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
602622
)
603623

624+
let start = DispatchTime.now()
625+
observabilityScope.emit(info: "retrieving \(package) \(version) manifest from \(request.url)")
604626
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
605627
completion(
606628
result.tryMap { response -> String in
629+
observabilityScope
630+
.emit(
631+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
632+
)
607633
switch response.statusCode {
608634
case 200:
609635
try response.validateAPIVersion(isOptional: true)
@@ -768,11 +794,17 @@ public final class RegistryClient: Cancellable {
768794
destination: downloadPath
769795
)
770796

797+
let downloadStart = DispatchTime.now()
798+
observabilityScope.emit(info: "downloading \(package) \(version) source archive from \(request.url)")
771799
self.httpClient
772800
.execute(request, observabilityScope: observabilityScope, progress: progressHandler) { result in
773801
switch result {
774802
case .success(let response):
775803
do {
804+
observabilityScope
805+
.emit(
806+
debug: "server response for \(request.url): \(response.statusCode) in \(downloadStart.distance(to: .now()).descriptionInSeconds)"
807+
)
776808
switch response.statusCode {
777809
case 200:
778810
try response.validateAPIVersion(isOptional: true)
@@ -784,6 +816,10 @@ public final class RegistryClient: Cancellable {
784816
let actualChecksum = checksumAlgorithm.hash(.init(archiveContent))
785817
.hexadecimalRepresentation
786818

819+
observabilityScope
820+
.emit(
821+
debug: "performing TOFU checks on \(package) \(version) source archive (checksum: '\(actualChecksum)'"
822+
)
787823
signatureValidation.validate(
788824
registry: registry,
789825
package: package,
@@ -821,6 +857,11 @@ public final class RegistryClient: Cancellable {
821857
recursive: true
822858
)
823859
// extract the content
860+
let extractStart = DispatchTime.now()
861+
observabilityScope
862+
.emit(
863+
debug: "extracting \(package) \(version) source archive to '\(destinationPath)'"
864+
)
824865
let archiver = self.archiverProvider(fileSystem)
825866
// TODO: Bail if archive contains relative paths or overlapping files
826867
archiver
@@ -831,6 +872,10 @@ public final class RegistryClient: Cancellable {
831872
defer {
832873
try? fileSystem.removeFileTree(downloadPath)
833874
}
875+
observabilityScope
876+
.emit(
877+
debug: "extracted \(package) \(version) source archive to '\(destinationPath)' in \(extractStart.distance(to: .now()).descriptionInSeconds)"
878+
)
834879
completion(result.tryMap {
835880
// strip first level component
836881
try fileSystem
@@ -841,6 +886,10 @@ public final class RegistryClient: Cancellable {
841886
component: RegistryReleaseMetadataStorage
842887
.fileName
843888
)
889+
observabilityScope
890+
.emit(
891+
debug: "saving \(package) \(version) metadata to '\(registryMetadataPath)'"
892+
)
844893
try RegistryReleaseMetadataStorage.save(
845894
metadata: versionMetadata,
846895
signingEntity: signingEntity,
@@ -976,15 +1025,22 @@ public final class RegistryClient: Cancellable {
9761025
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
9771026
)
9781027

1028+
let start = DispatchTime.now()
1029+
observabilityScope.emit(info: "looking up identity for \(scmURL) from \(request.url)")
9791030
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
9801031
completion(
9811032
result.tryMap { response in
1033+
observabilityScope
1034+
.emit(
1035+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
1036+
)
9821037
switch response.statusCode {
9831038
case 200:
9841039
let packageIdentities = try response.parseJSON(
9851040
Serialization.PackageIdentifiers.self,
9861041
decoder: self.jsonDecoder
9871042
)
1043+
observabilityScope.emit(debug: "matched identities for \(scmURL): \(packageIdentities)")
9881044
return Set(packageIdentities.identifiers.map {
9891045
PackageIdentity.plain($0)
9901046
})
@@ -1016,9 +1072,15 @@ public final class RegistryClient: Cancellable {
10161072
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
10171073
)
10181074

1075+
let start = DispatchTime.now()
1076+
observabilityScope.emit(info: "logging-in into \(request.url)")
10191077
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
10201078
completion(
10211079
result.tryMap { response in
1080+
observabilityScope
1081+
.emit(
1082+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
1083+
)
10221084
switch response.statusCode {
10231085
case 200:
10241086
return ()
@@ -1134,13 +1196,18 @@ public final class RegistryClient: Cancellable {
11341196
request.headers.add(name: "X-Swift-Package-Signature-Format", value: signatureFormat.rawValue)
11351197
}
11361198

1199+
let start = DispatchTime.now()
1200+
observabilityScope.emit(info: "publishing \(packageIdentity) \(packageVersion) to \(request.url)")
11371201
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
11381202
completion(
11391203
result.tryMap { response in
1204+
observabilityScope
1205+
.emit(
1206+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
1207+
)
11401208
switch response.statusCode {
11411209
case 201:
11421210
try response.validateAPIVersion()
1143-
11441211
let location = response.headers.get("Location").first.flatMap { URL(string: $0) }
11451212
return PublishResult.published(location)
11461213
case 202:
@@ -1190,9 +1257,15 @@ public final class RegistryClient: Cancellable {
11901257
options: self.defaultRequestOptions(timeout: timeout, callbackQueue: callbackQueue)
11911258
)
11921259

1260+
let start = DispatchTime.now()
1261+
observabilityScope.emit(info: "checking availability of \(registry.url) using \(request.url)")
11931262
self.httpClient.execute(request, observabilityScope: observabilityScope, progress: nil) { result in
11941263
completion(
11951264
result.tryMap { response in
1265+
observabilityScope
1266+
.emit(
1267+
debug: "server response for \(request.url): \(response.statusCode) in \(start.distance(to: .now()).descriptionInSeconds)"
1268+
)
11961269
switch response.statusCode {
11971270
case 200:
11981271
return .available

‎Sources/PackageRegistry/SignatureValidation.swift

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -140,6 +140,7 @@ struct SignatureValidation {
140140
completion: completion
141141
)
142142
} catch RegistryError.sourceArchiveNotSigned(let registry, let package, let version) {
143+
observabilityScope.emit(info: "\(package) \(version) from \(registry) is unsigned")
143144
guard let onUnsigned = configuration.onUnsigned else {
144145
return completion(.failure(RegistryError.missingConfiguration(details: "security.signing.onUnsigned")))
145146
}
@@ -209,12 +210,21 @@ struct SignatureValidation {
209210

210211
switch signatureStatus {
211212
case .valid(let signingEntity):
213+
observabilityScope
214+
.emit(
215+
info: "\(package) \(version) from \(registry) is signed with a valid entity '\(signingEntity)'"
216+
)
212217
completion(.success(signingEntity))
213218
case .invalid(let reason):
214219
completion(.failure(RegistryError.invalidSignature(reason: reason)))
215220
case .certificateInvalid(let reason):
216221
completion(.failure(RegistryError.invalidSigningCertificate(reason: reason)))
217222
case .certificateNotTrusted(let signingEntity):
223+
observabilityScope
224+
.emit(
225+
info: "\(package) \(version) from \(registry) signing entity '\(signingEntity)' is untrusted"
226+
)
227+
218228
guard let onUntrusted = configuration.onUntrustedCertificate else {
219229
return completion(.failure(
220230
RegistryError.missingConfiguration(details: "security.signing.onUntrustedCertificate")

0 commit comments

Comments
 (0)