Merge pull request #1474 from ahoppen/logging-doc

Add a document to describe which log level to use

Author: ahoppen

Documentation/Logging.md

@@ -0,0 +1,67 @@
+# Logging
+
+The following is a guide of how to write log messages and which level they should be logged at. There may be reasons to deviate from these guides but they should be a good starting point.
+
+## Log Levels
+
+The following log levels should be used by log messages in default. The [Explore logging in Swift](https://developer.apple.com/wwdc20/10168?time=604) session from WWDC20 has some explanation of how these levels are persisted by OS log and we follow those guidelines.
+
+### Fault
+
+> From Explore Logging in Swift: _Bug in program_
+
+A bug in SourceKit-LSP, sourcekitd or any other project included in the Swift toolchain that should never happen and is not due to malformed user input. The fix for faults should always be in a project controlled by the Swift toolchain (most likely in SourceKit-LSP itself) and we should never close them as a third party to resolve. Think of these as light assertions that don’t crash sourcekit-lsp because it is able to recover in some way.
+
+Examples:
+- Some global state invariant is broken like a file to `startProgress` not being followed by `endProgress`
+- sourcekitd crashes
+- Two targets in SwiftPM have the same name
+
+### Error
+
+> From Explore Logging in Swift: _Error seen during execution_
+
+An error that is due to user input or eg. stale state of files on disk. It indicates that something is going wrong which might explain unexpected behavior. Errors could be due to malformed user input such as invalid requests from the editor or due to stale state that will eventually converge again.
+
+Examples:
+- The client sends an invalid request
+- Preparation of a file failed due to a syntax error in the user’s code
+- The index contains a reference to a source file but the source fail has been modified since the index was last updated and is thus no longer valid
+
+## Log/Notice/Default
+
+`logger.default` logs at the `default` aka `notice` level.
+
+> From Explore Logging in Swift: _Essential for troubleshooting_
+
+Essential state transitions during SourceKit-LSP’s execution that allow use to determine what interactions the user performed. These logs will most likely be included in diagnose bundles from `sourcekit-lsp` diagnose and should help us solve most problems.
+
+Examples:
+- The user sends an LSP request
+- Indexing of a file starts or finishes
+- New build settings for a file have been computed
+- Responses from sourcekitd
+
+## Info
+
+> From Explore Logging in Swift: _Helpful but not essential for troubleshooting_ (not persisted, logged to memory)
+
+Internal state transitions that are helpful. If eg. a request fails and it’s not immediately obvious at which it failed, these should help us narrow down the code that it failed in. These messages might be missing from the logs generated by `sourcekit-lsp diagnose` and should not generally be needed to fix issues
+
+Examples:
+- Requests sent to `sourcekitd` or `clangd`
+- Logging the main file for a header file
+
+## Debug
+
+> From Explore Logging in Swift: _Useful only during debugging_ (only logged during debugging)
+
+Log messages that are useful eg. when debugging a test failure but that is not needed for diagnosing most real-world issues, like detailed information about when a function starts executing to diagnose race conditions.
+
+Examples:
+- Tasks start and finish executing in `TaskScheduler`
+
+## Log messages
+
+Log messages should resemble English sentences and start with an uppercase letter. If the log is a single sentence it should not have a period at its end.
+

Sources/LSPLogging/Logging.swift

@@ -10,15 +10,6 @@
 //
 //===----------------------------------------------------------------------===//
 
-/// Which log level to use (from https://developer.apple.com/wwdc20/10168?time=604)
-///  - Debug: Useful only during debugging (only logged during debugging)
-///  - Info: Helpful but not essential for troubleshooting (not persisted, logged to memory)
-///  - Notice/log/default: Essential for troubleshooting
-///  - Error: Error seen during execution
-///    - Used eg. if the user sends an erroneous request or if a request fails
-///  - Fault: Bug in program
-///    - Used eg. if invariants inside sourcekit-lsp are broken and the error is not due to user-provided input
-
 import Foundation
 
 #if canImport(os) && !SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER

Sources/LanguageServerProtocolJSONRPC/JSONRPCConnection.swift

@@ -134,7 +134,7 @@ public final class JSONRPCConnection: Connection {
       queue: queue,
       cleanupHandler: { (error: Int32) in
         if error != 0 {
-          logger.error("IO error \(error)")
+          logger.fault("IO error \(error)")
         }
         ioGroup.leave()
       }
@@ -153,7 +153,7 @@ public final class JSONRPCConnection: Connection {
       queue: sendQueue,
       cleanupHandler: { (error: Int32) in
         if error != 0 {
-          logger.error("IO error \(error)")
+          logger.fault("IO error \(error)")
         }
         ioGroup.leave()
       }
@@ -195,7 +195,7 @@ public final class JSONRPCConnection: Connection {
         guard errorCode == 0 else {
           #if !os(Windows)
           if errorCode != POSIXError.ECANCELED.rawValue {
-            logger.error("IO error reading \(errorCode)")
+            logger.fault("IO error reading \(errorCode)")
           }
           #endif
           if done { self.closeAssumingOnQueue() }
@@ -365,7 +365,7 @@ public final class JSONRPCConnection: Connection {
     precondition(state != .created, "tried to send message before calling start(messageHandler:)")
     let ready = state == .running
     if shouldLog && !ready {
-      logger.error("ignoring message; state = \(String(reflecting: self.state), privacy: .public)")
+      logger.error("Ignoring message; state = \(String(reflecting: self.state), privacy: .public)")
     }
     return ready
   }
@@ -444,7 +444,7 @@ public final class JSONRPCConnection: Connection {
 
     sendIO.write(offset: 0, data: dispatchData, queue: sendQueue) { [weak self] done, _, errorCode in
       if errorCode != 0 {
-        logger.error("IO error sending message \(errorCode)")
+        logger.fault("IO error sending message \(errorCode)")
         if done, let self {
           // An unrecoverable error occurs on the channel’s file descriptor.
           // Close the connection.
@@ -546,7 +546,7 @@ public final class JSONRPCConnection: Connection {
       guard state == .running else { return }
       state = .closed
 
-      logger.log("closing JSONRPCConnection...")
+      logger.log("Closing JSONRPCConnection...")
       // Attempt to close the reader immediately; we do not need to accept remaining inputs.
       receiveIO.close(flags: .stop)
       // Close the writer after it finishes outstanding work.

Sources/SKCore/BuildServerBuildSystem.swift

@@ -118,7 +118,7 @@ public actor BuildServerBuildSystem: MessageHandler {
       // config file was missing, no build server for this workspace
       return nil
     } catch {
-      logger.fault("failed to start build server: \(error.forLogging)")
+      logger.fault("Failed to start build server: \(error.forLogging)")
       return nil
     }
   }
@@ -127,7 +127,7 @@ public actor BuildServerBuildSystem: MessageHandler {
     if let buildServer = self.buildServer {
       _ = buildServer.send(ShutdownBuild()) { result in
         if let error = result.failure {
-          logger.fault("error shutting down build server: \(error.forLogging)")
+          logger.fault("Error shutting down build server: \(error.forLogging)")
         }
         buildServer.send(ExitBuildNotification())
         buildServer.close()
@@ -175,7 +175,7 @@ public actor BuildServerBuildSystem: MessageHandler {
     let buildServer = try makeJSONRPCBuildServer(client: self, serverPath: serverPath, serverFlags: flags)
     let response = try await buildServer.send(initializeRequest)
     buildServer.send(InitializedBuildNotification())
-    logger.log("initialized build server \(response.displayName)")
+    logger.log("Initialized build server \(response.displayName)")
 
     // see if index store was set as part of the server metadata
     if let indexDbPath = readReponseDataKey(data: response.data, key: "indexDatabasePath") {
@@ -307,7 +307,7 @@ extension BuildServerBuildSystem: BuildSystem {
     let request = RegisterForChanges(uri: uri, action: .register)
     _ = self.buildServer?.send(request) { result in
       if let error = result.failure {
-        logger.error("error registering \(uri): \(error.forLogging)")
+        logger.error("Error registering \(uri): \(error.forLogging)")
 
         Task {
           // BuildServer registration failed, so tell our delegate that no build
@@ -324,7 +324,7 @@ extension BuildServerBuildSystem: BuildSystem {
     let request = RegisterForChanges(uri: uri, action: .unregister)
     _ = self.buildServer?.send(request) { result in
       if let error = result.failure {
-        logger.error("error unregistering \(uri.forLogging): \(error.forLogging)")
+        logger.error("Error unregistering \(uri.forLogging): \(error.forLogging)")
       }
     }
   }
@@ -416,7 +416,7 @@ private func makeJSONRPCBuildServer(
   process.terminationHandler = { process in
     logger.log(
       level: process.terminationReason == .exit ? .default : .error,
-      "build server exited: \(String(reflecting: process.terminationReason)) \(process.terminationStatus)"
+      "Build server exited: \(String(reflecting: process.terminationReason)) \(process.terminationStatus)"
     )
     connection.close()
   }

Sources/SKCore/BuildSystemManager.swift

@@ -265,7 +265,7 @@ extension BuildSystemManager {
 
   public func unregisterForChangeNotifications(for uri: DocumentURI) async {
     guard let mainFile = self.watchedFiles[uri]?.mainFile else {
-      logger.error("Unbalanced calls for registerForChangeNotifications and unregisterForChangeNotifications")
+      logger.fault("Unbalanced calls for registerForChangeNotifications and unregisterForChangeNotifications")
       return
     }
     self.watchedFiles[uri] = nil

Sources/SKCore/CompilationDatabaseBuildSystem.swift

@@ -173,7 +173,7 @@ extension CompilationDatabaseBuildSystem: BuildSystem {
     }
 
     if compdb == nil {
-      logger.error("could not open compilation database for \(path)")
+      logger.error("Could not open compilation database for \(path)")
     }
 
     return compdb

Sources/SKSupport/Process+Run.swift

@@ -118,14 +118,14 @@ extension Process {
 private func setProcessPriority(pid: Process.ProcessID, newPriority: TaskPriority) {
   #if os(Windows)
   guard let handle = OpenProcess(UInt32(PROCESS_SET_INFORMATION), /*bInheritHandle*/ false, UInt32(pid)) else {
-    logger.error("Failed to get process handle for \(pid) to change its priority: \(GetLastError())")
+    logger.fault("Failed to get process handle for \(pid) to change its priority: \(GetLastError())")
     return
   }
   defer {
     CloseHandle(handle)
   }
   if !SetPriorityClass(handle, UInt32(newPriority.windowsProcessPriority)) {
-    logger.error("Failed to set process priority of \(pid) to \(newPriority.rawValue): \(GetLastError())")
+    logger.fault("Failed to set process priority of \(pid) to \(newPriority.rawValue): \(GetLastError())")
   }
   #elseif canImport(Darwin) || canImport(Android)
   // `setpriority` is only able to decrease a process's priority and cannot elevate it. Since Swift task’s priorities

Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift

@@ -305,7 +305,7 @@ public actor SwiftPMBuildSystem {
     } catch Error.noManifest {
       return nil
     } catch {
-      logger.error("failed to create SwiftPMWorkspace at \(uri.forLogging): \(error.forLogging)")
+      logger.error("Failed to create SwiftPMWorkspace at \(uri.forLogging): \(error.forLogging)")
       return nil
     }
   }
@@ -450,7 +450,7 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem {
     }
 
     guard let buildTarget = self.targets[configuredTarget]?.buildTarget else {
-      logger.error("Did not find target with name \(configuredTarget.targetID)")
+      logger.fault("Did not find target with name \(configuredTarget.targetID)")
       return nil
     }
 

Sources/SourceKitLSP/CapabilityRegistry.swift

@@ -141,7 +141,7 @@ public final actor CapabilityRegistry {
   ) async {
     if let registration = registration(for: languages, in: registrationDict) {
       if options != registration {
-        logger.error(
+        logger.fault(
           """
           Failed to dynamically register for \(method, privacy: .public) for \(languages, privacy: .public) \
           due to pre-existing options:
@@ -200,7 +200,7 @@ public final actor CapabilityRegistry {
     guard clientHasDynamicDidChangeWatchedFilesRegistration else { return }
     if let registration = didChangeWatchedFiles {
       if watchers != registration.watchers {
-        logger.error(
+        logger.fault(
           "Unable to register new file system watchers \(watchers) due to pre-existing options \(registration.watchers)"
         )
       }

Sources/SourceKitLSP/CreateBuildSystem.swift

@@ -29,7 +29,7 @@ func createBuildSystem(
     // We assume that workspaces are directories. This is only true for URLs not for URIs in general.
     // Simply skip setting up the build integration in this case.
     logger.error(
-      "cannot setup build integration at URI \(rootUri.forLogging) because the URI it is not a valid file URL"
+      "Cannot setup build integration at URI \(rootUri.forLogging) because the URI it is not a valid file URL"
     )
     return nil
   }

Sources/SourceKitLSP/Rename.swift

@@ -537,7 +537,7 @@ extension SourceKitLSPServer {
   ) async throws -> CrossLanguageName? {
     let definitions = index.occurrences(ofUSR: usr, roles: [.definition])
     if definitions.isEmpty {
-      logger.error("no definitions for \(usr) found")
+      logger.error("No definitions for \(usr) found")
       return nil
     }
     if definitions.count > 1 {

Sources/SourceKitLSP/SourceKitLSPServer.swift

@@ -931,7 +931,7 @@ extension SourceKitLSPServer {
     do {
       try await buildSystem?.generateBuildGraph(allowFileSystemWrites: true)
     } catch {
-      logger.error("failed to generate build graph at \(workspaceFolder.uri.forLogging): \(error.forLogging)")
+      logger.error("Failed to generate build graph at \(workspaceFolder.uri.forLogging): \(error.forLogging)")
       return nil
     }
 
@@ -990,7 +990,7 @@ extension SourceKitLSPServer {
         case .some(.int(let maxResults)):
           self.options.completionOptions.maxResults = maxResults
         case .some(let invalid):
-          logger.error("expected null or int for 'maxResults'; got \(String(reflecting: invalid))")
+          logger.error("Expected null or int for 'maxResults'; got \(String(reflecting: invalid))")
         }
       }
     }
@@ -1018,7 +1018,7 @@ extension SourceKitLSPServer {
       }
 
       if self.workspaces.isEmpty {
-        logger.error("no workspace found")
+        logger.error("No workspace found")
 
         let workspace = await Workspace(
           documentManager: self.documentManager,
@@ -1278,7 +1278,7 @@ extension SourceKitLSPServer {
     let uri = notification.textDocument.uri
     guard let workspace = await workspaceForDocument(uri: uri) else {
       logger.error(
-        "received open notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
+        "Received open notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
       )
       return
     }
@@ -1310,7 +1310,7 @@ extension SourceKitLSPServer {
     let uri = notification.textDocument.uri
     guard let workspace = await workspaceForDocument(uri: uri) else {
       logger.error(
-        "received close notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
+        "Received close notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
       )
       return
     }
@@ -1321,7 +1321,7 @@ extension SourceKitLSPServer {
     let uri = notification.textDocument.uri
     guard let workspace = await workspaceForDocument(uri: uri) else {
       logger.error(
-        "received reopen notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
+        "Received reopen notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
       )
       return
     }
@@ -1345,7 +1345,7 @@ extension SourceKitLSPServer {
 
     guard let workspace = await workspaceForDocument(uri: uri) else {
       logger.error(
-        "received change notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
+        "Received change notification for file '\(uri.forLogging)' without a corresponding workspace, ignoring..."
       )
       return
     }
@@ -1597,7 +1597,7 @@ extension SourceKitLSPServer {
 
   func executeCommand(_ req: ExecuteCommandRequest) async throws -> LSPAny? {
     guard let uri = req.textDocument?.uri else {
-      logger.error("attempted to perform executeCommand request without an url!")
+      logger.error("Attempted to perform executeCommand request without an URL")
       return nil
     }
     guard let workspace = await workspaceForDocument(uri: uri) else {
@@ -1704,7 +1704,7 @@ extension SourceKitLSPServer {
       }
     }
     guard let usr = symbol.usr else { return [] }
-    logger.info("performing indexed jump-to-def with usr \(usr)")
+    logger.info("Performing indexed jump-to-definition with USR \(usr)")
     var occurrences = index.definitionOrDeclarationOccurrences(ofUSR: usr)
     if symbol.isDynamic ?? true {
       lazy var transitiveReceiverUsrs: [String]? = {

Sources/SourceKitLSP/Swift/Diagnostic.swift

@@ -32,7 +32,7 @@ extension CodeAction {
     }
 
     if !editsMapped {
-      logger.fault("failed to construct TextEdits from response \(fixits)")
+      logger.fault("Failed to construct TextEdits from response \(fixits)")
       return nil
     }
 
@@ -374,7 +374,7 @@ extension DiagnosticStage {
       self = .sema
     default:
       let desc = sourcekitd.api.uid_get_string_ptr(uid).map { String(cString: $0) }
-      logger.fault("unknown diagnostic stage \(desc ?? "nil", privacy: .public)")
+      logger.fault("Unknown diagnostic stage \(desc ?? "nil", privacy: .public)")
       return nil
     }
   }

Sources/SourceKitLSP/Swift/RewriteSourceKitPlaceholders.swift

@@ -18,12 +18,12 @@ func rewriteSourceKitPlaceholders(in string: String, clientSupportsSnippets: Boo
   var index = 1
   while let start = result.range(of: "<#") {
     guard let end = result[start.upperBound...].range(of: "#>") else {
-      logger.error("invalid placeholder in \(string)")
+      logger.fault("Invalid placeholder in \(string)")
       return string
     }
     let rawPlaceholder = String(result[start.lowerBound..<end.upperBound])
     guard let displayName = EditorPlaceholderData(text: rawPlaceholder)?.nameForSnippet else {
-      logger.error("failed to decode placeholder \(rawPlaceholder) in \(string)")
+      logger.fault("Failed to decode placeholder \(rawPlaceholder) in \(string)")
       return string
     }
     let snippet = clientSupportsSnippets ? "${\(index):\(displayName)}" : ""