LoggingTest.swift 36 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903
  1. //===----------------------------------------------------------------------===//
  2. //
  3. // This source file is part of the Swift Logging API open source project
  4. //
  5. // Copyright (c) 2018-2019 Apple Inc. and the Swift Logging API project authors
  6. // Licensed under Apache License v2.0
  7. //
  8. // See LICENSE.txt for license information
  9. // See CONTRIBUTORS.txt for the list of Swift Logging API project authors
  10. //
  11. // SPDX-License-Identifier: Apache-2.0
  12. //
  13. //===----------------------------------------------------------------------===//
  14. @testable import Logging
  15. import XCTest
  16. #if os(macOS) || os(iOS) || os(tvOS) || os(watchOS)
  17. import Darwin
  18. #elseif os(Windows)
  19. import WinSDK
  20. #else
  21. import Glibc
  22. #endif
  23. class LoggingTest: XCTestCase {
  24. func testAutoclosure() throws {
  25. // bootstrap with our test logging impl
  26. let logging = TestLogging()
  27. LoggingSystem.bootstrapInternal(logging.make)
  28. var logger = Logger(label: "test")
  29. logger.logLevel = .info
  30. logger.log(level: .debug, {
  31. XCTFail("debug should not be called")
  32. return "debug"
  33. }())
  34. logger.trace({
  35. XCTFail("trace should not be called")
  36. return "trace"
  37. }())
  38. logger.debug({
  39. XCTFail("debug should not be called")
  40. return "debug"
  41. }())
  42. logger.info({
  43. "info"
  44. }())
  45. logger.warning({
  46. "warning"
  47. }())
  48. logger.error({
  49. "error"
  50. }())
  51. XCTAssertEqual(3, logging.history.entries.count, "expected number of entries to match")
  52. logging.history.assertNotExist(level: .debug, message: "trace")
  53. logging.history.assertNotExist(level: .debug, message: "debug")
  54. logging.history.assertExist(level: .info, message: "info")
  55. logging.history.assertExist(level: .warning, message: "warning")
  56. logging.history.assertExist(level: .error, message: "error")
  57. }
  58. func testMultiplex() throws {
  59. // bootstrap with our test logging impl
  60. let logging1 = TestLogging()
  61. let logging2 = TestLogging()
  62. LoggingSystem.bootstrapInternal { MultiplexLogHandler([logging1.make(label: $0), logging2.make(label: $0)]) }
  63. var logger = Logger(label: "test")
  64. logger.logLevel = .warning
  65. logger.info("hello world?")
  66. logger[metadataKey: "foo"] = "bar"
  67. logger.warning("hello world!")
  68. logging1.history.assertNotExist(level: .info, message: "hello world?")
  69. logging2.history.assertNotExist(level: .info, message: "hello world?")
  70. logging1.history.assertExist(level: .warning, message: "hello world!", metadata: ["foo": "bar"])
  71. logging2.history.assertExist(level: .warning, message: "hello world!", metadata: ["foo": "bar"])
  72. }
  73. func testMultiplexLogHandlerWithVariousLogLevels() throws {
  74. let logging1 = TestLogging()
  75. let logging2 = TestLogging()
  76. var logger1 = logging1.make(label: "1")
  77. logger1.logLevel = .info
  78. var logger2 = logging2.make(label: "2")
  79. logger2.logLevel = .debug
  80. LoggingSystem.bootstrapInternal { _ in
  81. MultiplexLogHandler([logger1, logger2])
  82. }
  83. let multiplexLogger = Logger(label: "test")
  84. multiplexLogger.trace("trace")
  85. multiplexLogger.debug("debug")
  86. multiplexLogger.info("info")
  87. multiplexLogger.warning("warning")
  88. logging1.history.assertNotExist(level: .trace, message: "trace")
  89. logging1.history.assertNotExist(level: .debug, message: "debug")
  90. logging1.history.assertExist(level: .info, message: "info")
  91. logging1.history.assertExist(level: .warning, message: "warning")
  92. logging2.history.assertNotExist(level: .trace, message: "trace")
  93. logging2.history.assertExist(level: .debug, message: "debug")
  94. logging2.history.assertExist(level: .info, message: "info")
  95. logging2.history.assertExist(level: .warning, message: "warning")
  96. }
  97. func testMultiplexLogHandlerNeedNotMaterializeValuesMultipleTimes() throws {
  98. let logging1 = TestLogging()
  99. let logging2 = TestLogging()
  100. var logger1 = logging1.make(label: "1")
  101. logger1.logLevel = .info
  102. var logger2 = logging2.make(label: "2")
  103. logger2.logLevel = .info
  104. LoggingSystem.bootstrapInternal { _ in
  105. MultiplexLogHandler([logger1, logger2])
  106. }
  107. var messageMaterializations: Int = 0
  108. var metadataMaterializations: Int = 0
  109. let multiplexLogger = Logger(label: "test")
  110. multiplexLogger.info(
  111. { () -> Logger.Message in
  112. messageMaterializations += 1
  113. return "info"
  114. }(),
  115. metadata: { () ->
  116. Logger.Metadata in metadataMaterializations += 1
  117. return [:]
  118. }()
  119. )
  120. logging1.history.assertExist(level: .info, message: "info")
  121. logging2.history.assertExist(level: .info, message: "info")
  122. XCTAssertEqual(messageMaterializations, 1)
  123. XCTAssertEqual(metadataMaterializations, 1)
  124. }
  125. func testMultiplexLogHandlerMetadata_settingMetadataThroughToUnderlyingHandlers() {
  126. let logging1 = TestLogging()
  127. let logging2 = TestLogging()
  128. var logger1 = logging1.make(label: "1")
  129. logger1.metadata["one"] = "111"
  130. logger1.metadata["in"] = "in-1"
  131. var logger2 = logging2.make(label: "2")
  132. logger2.metadata["two"] = "222"
  133. logger2.metadata["in"] = "in-2"
  134. LoggingSystem.bootstrapInternal { _ in
  135. MultiplexLogHandler([logger1, logger2])
  136. }
  137. var multiplexLogger = Logger(label: "test")
  138. // each logs its own metadata
  139. multiplexLogger.info("info")
  140. logging1.history.assertExist(level: .info, message: "info", metadata: [
  141. "one": "111",
  142. "in": "in-1",
  143. ])
  144. logging2.history.assertExist(level: .info, message: "info", metadata: [
  145. "two": "222",
  146. "in": "in-2",
  147. ])
  148. // if modified, change applies to both underlying handlers
  149. multiplexLogger[metadataKey: "new"] = "new"
  150. multiplexLogger.info("info")
  151. logging1.history.assertExist(level: .info, message: "info", metadata: [
  152. "one": "111",
  153. "in": "in-1",
  154. "new": "new",
  155. ])
  156. logging2.history.assertExist(level: .info, message: "info", metadata: [
  157. "two": "222",
  158. "in": "in-2",
  159. "new": "new",
  160. ])
  161. // overriding an existing value works the same way as adding a new one
  162. multiplexLogger[metadataKey: "in"] = "multi"
  163. multiplexLogger.info("info")
  164. logging1.history.assertExist(level: .info, message: "info", metadata: [
  165. "one": "111",
  166. "in": "multi",
  167. "new": "new",
  168. ])
  169. logging2.history.assertExist(level: .info, message: "info", metadata: [
  170. "two": "222",
  171. "in": "multi",
  172. "new": "new",
  173. ])
  174. }
  175. func testMultiplexLogHandlerMetadata_readingHandlerMetadata() {
  176. let logging1 = TestLogging()
  177. let logging2 = TestLogging()
  178. var logger1 = logging1.make(label: "1")
  179. logger1.metadata["one"] = "111"
  180. logger1.metadata["in"] = "in-1"
  181. var logger2 = logging2.make(label: "2")
  182. logger2.metadata["two"] = "222"
  183. logger2.metadata["in"] = "in-2"
  184. LoggingSystem.bootstrapInternal { _ in
  185. MultiplexLogHandler([logger1, logger2])
  186. }
  187. let multiplexLogger = Logger(label: "test")
  188. XCTAssertEqual(multiplexLogger.handler.metadata, [
  189. "one": "111",
  190. "two": "222",
  191. "in": "in-1",
  192. ])
  193. }
  194. enum TestError: Error {
  195. case boom
  196. }
  197. func testDictionaryMetadata() {
  198. let testLogging = TestLogging()
  199. LoggingSystem.bootstrapInternal(testLogging.make)
  200. var logger = Logger(label: "\(#function)")
  201. logger[metadataKey: "foo"] = ["bar": "buz"]
  202. logger[metadataKey: "empty-dict"] = [:]
  203. logger[metadataKey: "nested-dict"] = ["l1key": ["l2key": ["l3key": "l3value"]]]
  204. logger.info("hello world!")
  205. testLogging.history.assertExist(level: .info,
  206. message: "hello world!",
  207. metadata: ["foo": ["bar": "buz"],
  208. "empty-dict": [:],
  209. "nested-dict": ["l1key": ["l2key": ["l3key": "l3value"]]]])
  210. }
  211. func testListMetadata() {
  212. let testLogging = TestLogging()
  213. LoggingSystem.bootstrapInternal(testLogging.make)
  214. var logger = Logger(label: "\(#function)")
  215. logger[metadataKey: "foo"] = ["bar", "buz"]
  216. logger[metadataKey: "empty-list"] = []
  217. logger[metadataKey: "nested-list"] = ["l1str", ["l2str1", "l2str2"]]
  218. logger.info("hello world!")
  219. testLogging.history.assertExist(level: .info,
  220. message: "hello world!",
  221. metadata: ["foo": ["bar", "buz"],
  222. "empty-list": [],
  223. "nested-list": ["l1str", ["l2str1", "l2str2"]]])
  224. }
  225. // Example of custom "box" which may be used to implement "render at most once" semantics
  226. // Not thread-safe, thus should not be shared across threads.
  227. internal final class LazyMetadataBox: CustomStringConvertible {
  228. private var makeValue: (() -> String)?
  229. private var _value: String?
  230. public init(_ makeValue: @escaping () -> String) {
  231. self.makeValue = makeValue
  232. }
  233. /// This allows caching a value in case it is accessed via an by name subscript,
  234. // rather than as part of rendering all metadata that a LoggingContext was carrying
  235. public var value: String {
  236. if let f = self.makeValue {
  237. self._value = f()
  238. self.makeValue = nil
  239. }
  240. assert(self._value != nil, "_value MUST NOT be nil once `lazyValue` has run.")
  241. return self._value!
  242. }
  243. public var description: String {
  244. return "\(self.value)"
  245. }
  246. }
  247. func testStringConvertibleMetadata() {
  248. let testLogging = TestLogging()
  249. LoggingSystem.bootstrapInternal(testLogging.make)
  250. var logger = Logger(label: "\(#function)")
  251. logger[metadataKey: "foo"] = .stringConvertible("raw-string")
  252. let lazyBox = LazyMetadataBox { "rendered-at-first-use" }
  253. logger[metadataKey: "lazy"] = .stringConvertible(lazyBox)
  254. logger.info("hello world!")
  255. testLogging.history.assertExist(level: .info,
  256. message: "hello world!",
  257. metadata: ["foo": .stringConvertible("raw-string"),
  258. "lazy": .stringConvertible(LazyMetadataBox { "rendered-at-first-use" })])
  259. }
  260. private func dontEvaluateThisString(file: StaticString = #file, line: UInt = #line) -> Logger.Message {
  261. XCTFail("should not have been evaluated", file: file, line: line)
  262. return "should not have been evaluated"
  263. }
  264. func testAutoClosuresAreNotForcedUnlessNeeded() {
  265. let testLogging = TestLogging()
  266. LoggingSystem.bootstrapInternal(testLogging.make)
  267. var logger = Logger(label: "\(#function)")
  268. logger.logLevel = .error
  269. logger.debug(self.dontEvaluateThisString(), metadata: ["foo": "\(self.dontEvaluateThisString())"])
  270. logger.debug(self.dontEvaluateThisString())
  271. logger.info(self.dontEvaluateThisString())
  272. logger.warning(self.dontEvaluateThisString())
  273. logger.log(level: .warning, self.dontEvaluateThisString())
  274. }
  275. func testLocalMetadata() {
  276. let testLogging = TestLogging()
  277. LoggingSystem.bootstrapInternal(testLogging.make)
  278. var logger = Logger(label: "\(#function)")
  279. logger.info("hello world!", metadata: ["foo": "bar"])
  280. logger[metadataKey: "bar"] = "baz"
  281. logger[metadataKey: "baz"] = "qux"
  282. logger.warning("hello world!")
  283. logger.error("hello world!", metadata: ["baz": "quc"])
  284. testLogging.history.assertExist(level: .info, message: "hello world!", metadata: ["foo": "bar"])
  285. testLogging.history.assertExist(level: .warning, message: "hello world!", metadata: ["bar": "baz", "baz": "qux"])
  286. testLogging.history.assertExist(level: .error, message: "hello world!", metadata: ["bar": "baz", "baz": "quc"])
  287. }
  288. func testCustomFactory() {
  289. struct CustomHandler: LogHandler {
  290. func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?, source: String, file: String, function: String, line: UInt) {}
  291. subscript(metadataKey _: String) -> Logger.Metadata.Value? {
  292. get { return nil }
  293. set {}
  294. }
  295. var metadata: Logger.Metadata {
  296. get { return Logger.Metadata() }
  297. set {}
  298. }
  299. var logLevel: Logger.Level {
  300. get { return .info }
  301. set {}
  302. }
  303. }
  304. let logger1 = Logger(label: "foo")
  305. XCTAssertFalse(logger1.handler is CustomHandler, "expected non-custom log handler")
  306. let logger2 = Logger(label: "foo", factory: { _ in CustomHandler() })
  307. XCTAssertTrue(logger2.handler is CustomHandler, "expected custom log handler")
  308. }
  309. func testAllLogLevelsExceptCriticalCanBeBlocked() {
  310. let testLogging = TestLogging()
  311. LoggingSystem.bootstrapInternal(testLogging.make)
  312. var logger = Logger(label: "\(#function)")
  313. logger.logLevel = .critical
  314. logger.trace("no")
  315. logger.debug("no")
  316. logger.info("no")
  317. logger.notice("no")
  318. logger.warning("no")
  319. logger.error("no")
  320. logger.critical("yes: critical")
  321. testLogging.history.assertNotExist(level: .trace, message: "no")
  322. testLogging.history.assertNotExist(level: .debug, message: "no")
  323. testLogging.history.assertNotExist(level: .info, message: "no")
  324. testLogging.history.assertNotExist(level: .notice, message: "no")
  325. testLogging.history.assertNotExist(level: .warning, message: "no")
  326. testLogging.history.assertNotExist(level: .error, message: "no")
  327. testLogging.history.assertExist(level: .critical, message: "yes: critical")
  328. }
  329. func testAllLogLevelsWork() {
  330. let testLogging = TestLogging()
  331. LoggingSystem.bootstrapInternal(testLogging.make)
  332. var logger = Logger(label: "\(#function)")
  333. logger.logLevel = .trace
  334. logger.trace("yes: trace")
  335. logger.debug("yes: debug")
  336. logger.info("yes: info")
  337. logger.notice("yes: notice")
  338. logger.warning("yes: warning")
  339. logger.error("yes: error")
  340. logger.critical("yes: critical")
  341. testLogging.history.assertExist(level: .trace, message: "yes: trace")
  342. testLogging.history.assertExist(level: .debug, message: "yes: debug")
  343. testLogging.history.assertExist(level: .info, message: "yes: info")
  344. testLogging.history.assertExist(level: .notice, message: "yes: notice")
  345. testLogging.history.assertExist(level: .warning, message: "yes: warning")
  346. testLogging.history.assertExist(level: .error, message: "yes: error")
  347. testLogging.history.assertExist(level: .critical, message: "yes: critical")
  348. }
  349. func testAllLogLevelByFunctionRefWithSource() {
  350. let testLogging = TestLogging()
  351. LoggingSystem.bootstrapInternal(testLogging.make)
  352. var logger = Logger(label: "\(#function)")
  353. logger.logLevel = .trace
  354. let trace = logger.trace(_:metadata:source:file:function:line:)
  355. let debug = logger.debug(_:metadata:source:file:function:line:)
  356. let info = logger.info(_:metadata:source:file:function:line:)
  357. let notice = logger.notice(_:metadata:source:file:function:line:)
  358. let warning = logger.warning(_:metadata:source:file:function:line:)
  359. let error = logger.error(_:metadata:source:file:function:line:)
  360. let critical = logger.critical(_:metadata:source:file:function:line:)
  361. trace("yes: trace", [:], "foo", #file, #function, #line)
  362. debug("yes: debug", [:], "foo", #file, #function, #line)
  363. info("yes: info", [:], "foo", #file, #function, #line)
  364. notice("yes: notice", [:], "foo", #file, #function, #line)
  365. warning("yes: warning", [:], "foo", #file, #function, #line)
  366. error("yes: error", [:], "foo", #file, #function, #line)
  367. critical("yes: critical", [:], "foo", #file, #function, #line)
  368. testLogging.history.assertExist(level: .trace, message: "yes: trace", source: "foo")
  369. testLogging.history.assertExist(level: .debug, message: "yes: debug", source: "foo")
  370. testLogging.history.assertExist(level: .info, message: "yes: info", source: "foo")
  371. testLogging.history.assertExist(level: .notice, message: "yes: notice", source: "foo")
  372. testLogging.history.assertExist(level: .warning, message: "yes: warning", source: "foo")
  373. testLogging.history.assertExist(level: .error, message: "yes: error", source: "foo")
  374. testLogging.history.assertExist(level: .critical, message: "yes: critical", source: "foo")
  375. }
  376. func testAllLogLevelByFunctionRefWithoutSource() {
  377. let testLogging = TestLogging()
  378. LoggingSystem.bootstrapInternal(testLogging.make)
  379. var logger = Logger(label: "\(#function)")
  380. logger.logLevel = .trace
  381. let trace = logger.trace(_:metadata:file:function:line:)
  382. let debug = logger.debug(_:metadata:file:function:line:)
  383. let info = logger.info(_:metadata:file:function:line:)
  384. let notice = logger.notice(_:metadata:file:function:line:)
  385. let warning = logger.warning(_:metadata:file:function:line:)
  386. let error = logger.error(_:metadata:file:function:line:)
  387. let critical = logger.critical(_:metadata:file:function:line:)
  388. #if compiler(>=5.3)
  389. trace("yes: trace", [:], #fileID, #function, #line)
  390. debug("yes: debug", [:], #fileID, #function, #line)
  391. info("yes: info", [:], #fileID, #function, #line)
  392. notice("yes: notice", [:], #fileID, #function, #line)
  393. warning("yes: warning", [:], #fileID, #function, #line)
  394. error("yes: error", [:], #fileID, #function, #line)
  395. critical("yes: critical", [:], #fileID, #function, #line)
  396. #else
  397. trace("yes: trace", [:], #file, #function, #line)
  398. debug("yes: debug", [:], #file, #function, #line)
  399. info("yes: info", [:], #file, #function, #line)
  400. notice("yes: notice", [:], #file, #function, #line)
  401. warning("yes: warning", [:], #file, #function, #line)
  402. error("yes: error", [:], #file, #function, #line)
  403. critical("yes: critical", [:], #file, #function, #line)
  404. #endif
  405. testLogging.history.assertExist(level: .trace, message: "yes: trace")
  406. testLogging.history.assertExist(level: .debug, message: "yes: debug")
  407. testLogging.history.assertExist(level: .info, message: "yes: info")
  408. testLogging.history.assertExist(level: .notice, message: "yes: notice")
  409. testLogging.history.assertExist(level: .warning, message: "yes: warning")
  410. testLogging.history.assertExist(level: .error, message: "yes: error")
  411. testLogging.history.assertExist(level: .critical, message: "yes: critical")
  412. }
  413. func testLogsEmittedFromSubdirectoryGetCorrectModuleInNewerSwifts() {
  414. let testLogging = TestLogging()
  415. LoggingSystem.bootstrapInternal(testLogging.make)
  416. var logger = Logger(label: "\(#function)")
  417. logger.logLevel = .trace
  418. emitLogMessage("hello", to: logger)
  419. #if compiler(>=5.3)
  420. let moduleName = "LoggingTests" // the actual name
  421. #else
  422. let moduleName = "SubDirectoryOfLoggingTests" // the last path component of `#file` showing the failure mode
  423. #endif
  424. testLogging.history.assertExist(level: .trace, message: "hello", source: moduleName)
  425. testLogging.history.assertExist(level: .debug, message: "hello", source: moduleName)
  426. testLogging.history.assertExist(level: .info, message: "hello", source: moduleName)
  427. testLogging.history.assertExist(level: .notice, message: "hello", source: moduleName)
  428. testLogging.history.assertExist(level: .warning, message: "hello", source: moduleName)
  429. testLogging.history.assertExist(level: .error, message: "hello", source: moduleName)
  430. testLogging.history.assertExist(level: .critical, message: "hello", source: moduleName)
  431. }
  432. func testLogMessageWithStringInterpolation() {
  433. let testLogging = TestLogging()
  434. LoggingSystem.bootstrapInternal(testLogging.make)
  435. var logger = Logger(label: "\(#function)")
  436. logger.logLevel = .debug
  437. let someInt = Int.random(in: 23 ..< 42)
  438. logger.debug("My favourite number is \(someInt) and not \(someInt - 1)")
  439. testLogging.history.assertExist(level: .debug,
  440. message: "My favourite number is \(someInt) and not \(someInt - 1)" as String)
  441. }
  442. func testLoggingAString() {
  443. let testLogging = TestLogging()
  444. LoggingSystem.bootstrapInternal(testLogging.make)
  445. var logger = Logger(label: "\(#function)")
  446. logger.logLevel = .debug
  447. let anActualString: String = "hello world!"
  448. // We can't stick an actual String in here because we expect a Logger.Message. If we want to log an existing
  449. // `String`, we can use string interpolation. The error you'll get trying to use the String directly is:
  450. //
  451. // error: Cannot convert value of type 'String' to expected argument type 'Logger.Message'
  452. logger.debug("\(anActualString)")
  453. testLogging.history.assertExist(level: .debug, message: "hello world!")
  454. }
  455. func testMultiplexerIsValue() {
  456. let multi = MultiplexLogHandler([StreamLogHandler.standardOutput(label: "x"), StreamLogHandler.standardOutput(label: "y")])
  457. LoggingSystem.bootstrapInternal { _ in
  458. print("new multi")
  459. return multi
  460. }
  461. let logger1: Logger = {
  462. var logger = Logger(label: "foo")
  463. logger.logLevel = .debug
  464. logger[metadataKey: "only-on"] = "first"
  465. return logger
  466. }()
  467. XCTAssertEqual(.debug, logger1.logLevel)
  468. var logger2 = logger1
  469. logger2.logLevel = .error
  470. logger2[metadataKey: "only-on"] = "second"
  471. XCTAssertEqual(.error, logger2.logLevel)
  472. XCTAssertEqual(.debug, logger1.logLevel)
  473. XCTAssertEqual("first", logger1[metadataKey: "only-on"])
  474. XCTAssertEqual("second", logger2[metadataKey: "only-on"])
  475. logger1.error("hey")
  476. }
  477. func testLoggerWithGlobalOverride() {
  478. struct LogHandlerWithGlobalLogLevelOverride: LogHandler {
  479. // the static properties hold the globally overridden log level (if overridden)
  480. private static let overrideLock = Lock()
  481. private static var overrideLogLevel: Logger.Level?
  482. private let recorder: Recorder
  483. // this holds the log level if not overridden
  484. private var _logLevel: Logger.Level = .info
  485. // metadata storage
  486. var metadata: Logger.Metadata = [:]
  487. init(recorder: Recorder) {
  488. self.recorder = recorder
  489. }
  490. var logLevel: Logger.Level {
  491. // when we get asked for the log level, we check if it was globally overridden or not
  492. get {
  493. return LogHandlerWithGlobalLogLevelOverride.overrideLock.withLock {
  494. LogHandlerWithGlobalLogLevelOverride.overrideLogLevel
  495. } ?? self._logLevel
  496. }
  497. // we set the log level whenever we're asked (note: this might not have an effect if globally
  498. // overridden)
  499. set {
  500. self._logLevel = newValue
  501. }
  502. }
  503. func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?,
  504. source: String, file: String, function: String, line: UInt) {
  505. self.recorder.record(level: level, metadata: metadata, message: message, source: source)
  506. }
  507. subscript(metadataKey metadataKey: String) -> Logger.Metadata.Value? {
  508. get {
  509. return self.metadata[metadataKey]
  510. }
  511. set(newValue) {
  512. self.metadata[metadataKey] = newValue
  513. }
  514. }
  515. // this is the function to globally override the log level, it is not part of the `LogHandler` protocol
  516. static func overrideGlobalLogLevel(_ logLevel: Logger.Level) {
  517. LogHandlerWithGlobalLogLevelOverride.overrideLock.withLock {
  518. LogHandlerWithGlobalLogLevelOverride.overrideLogLevel = logLevel
  519. }
  520. }
  521. }
  522. let logRecorder = Recorder()
  523. LoggingSystem.bootstrapInternal { _ in
  524. LogHandlerWithGlobalLogLevelOverride(recorder: logRecorder)
  525. }
  526. var logger1 = Logger(label: "logger-\(#file):\(#line)")
  527. var logger2 = logger1
  528. logger1.logLevel = .warning
  529. logger1[metadataKey: "only-on"] = "first"
  530. logger2.logLevel = .error
  531. logger2[metadataKey: "only-on"] = "second"
  532. XCTAssertEqual(.error, logger2.logLevel)
  533. XCTAssertEqual(.warning, logger1.logLevel)
  534. XCTAssertEqual("first", logger1[metadataKey: "only-on"])
  535. XCTAssertEqual("second", logger2[metadataKey: "only-on"])
  536. logger1.notice("logger1, before")
  537. logger2.notice("logger2, before")
  538. LogHandlerWithGlobalLogLevelOverride.overrideGlobalLogLevel(.debug)
  539. logger1.notice("logger1, after")
  540. logger2.notice("logger2, after")
  541. logRecorder.assertNotExist(level: .notice, message: "logger1, before")
  542. logRecorder.assertNotExist(level: .notice, message: "logger2, before")
  543. logRecorder.assertExist(level: .notice, message: "logger1, after")
  544. logRecorder.assertExist(level: .notice, message: "logger2, after")
  545. }
  546. func testLogLevelCases() {
  547. let levels = Logger.Level.allCases
  548. XCTAssertEqual(7, levels.count)
  549. }
  550. func testLogLevelOrdering() {
  551. XCTAssertLessThan(Logger.Level.trace, Logger.Level.debug)
  552. XCTAssertLessThan(Logger.Level.trace, Logger.Level.info)
  553. XCTAssertLessThan(Logger.Level.trace, Logger.Level.notice)
  554. XCTAssertLessThan(Logger.Level.trace, Logger.Level.warning)
  555. XCTAssertLessThan(Logger.Level.trace, Logger.Level.error)
  556. XCTAssertLessThan(Logger.Level.trace, Logger.Level.critical)
  557. XCTAssertLessThan(Logger.Level.debug, Logger.Level.info)
  558. XCTAssertLessThan(Logger.Level.debug, Logger.Level.notice)
  559. XCTAssertLessThan(Logger.Level.debug, Logger.Level.warning)
  560. XCTAssertLessThan(Logger.Level.debug, Logger.Level.error)
  561. XCTAssertLessThan(Logger.Level.debug, Logger.Level.critical)
  562. XCTAssertLessThan(Logger.Level.info, Logger.Level.notice)
  563. XCTAssertLessThan(Logger.Level.info, Logger.Level.warning)
  564. XCTAssertLessThan(Logger.Level.info, Logger.Level.error)
  565. XCTAssertLessThan(Logger.Level.info, Logger.Level.critical)
  566. XCTAssertLessThan(Logger.Level.notice, Logger.Level.warning)
  567. XCTAssertLessThan(Logger.Level.notice, Logger.Level.error)
  568. XCTAssertLessThan(Logger.Level.notice, Logger.Level.critical)
  569. XCTAssertLessThan(Logger.Level.warning, Logger.Level.error)
  570. XCTAssertLessThan(Logger.Level.warning, Logger.Level.critical)
  571. XCTAssertLessThan(Logger.Level.error, Logger.Level.critical)
  572. }
  573. final class InterceptStream: TextOutputStream {
  574. var interceptedText: String?
  575. var strings = [String]()
  576. func write(_ string: String) {
  577. // This is a test implementation, a real implementation would include locking
  578. self.strings.append(string)
  579. self.interceptedText = (self.interceptedText ?? "") + string
  580. }
  581. }
  582. func testStreamLogHandlerWritesToAStream() {
  583. let interceptStream = InterceptStream()
  584. LoggingSystem.bootstrapInternal { _ in
  585. StreamLogHandler(label: "test", stream: interceptStream)
  586. }
  587. let log = Logger(label: "test")
  588. let testString = "my message is better than yours"
  589. log.critical("\(testString)")
  590. let messageSucceeded = interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).hasSuffix(testString)
  591. XCTAssertTrue(messageSucceeded ?? false)
  592. XCTAssertEqual(interceptStream.strings.count, 1)
  593. }
  594. func testStreamLogHandlerOutputFormat() {
  595. let interceptStream = InterceptStream()
  596. let label = "testLabel"
  597. LoggingSystem.bootstrapInternal { _ in
  598. StreamLogHandler(label: label, stream: interceptStream)
  599. }
  600. let source = "testSource"
  601. let log = Logger(label: label)
  602. let testString = "my message is better than yours"
  603. log.critical("\(testString)", source: source)
  604. let pattern = "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label)\\s:\\s\\[\(source)\\]\\s\(testString)$"
  605. let messageSucceeded = interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).range(of: pattern, options: .regularExpression) != nil
  606. XCTAssertTrue(messageSucceeded)
  607. XCTAssertEqual(interceptStream.strings.count, 1)
  608. }
  609. func testStreamLogHandlerOutputFormatWithMetaData() {
  610. let interceptStream = InterceptStream()
  611. let label = "testLabel"
  612. LoggingSystem.bootstrapInternal { _ in
  613. StreamLogHandler(label: label, stream: interceptStream)
  614. }
  615. let source = "testSource"
  616. let log = Logger(label: label)
  617. let testString = "my message is better than yours"
  618. log.critical("\(testString)", metadata: ["test": "test"], source: source)
  619. let pattern = "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label)\\s:\\stest=test\\s\\[\(source)\\]\\s\(testString)$"
  620. let messageSucceeded = interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).range(of: pattern, options: .regularExpression) != nil
  621. XCTAssertTrue(messageSucceeded)
  622. XCTAssertEqual(interceptStream.strings.count, 1)
  623. }
  624. func testStreamLogHandlerOutputFormatWithOrderedMetadata() {
  625. let interceptStream = InterceptStream()
  626. let label = "testLabel"
  627. LoggingSystem.bootstrapInternal { _ in
  628. StreamLogHandler(label: label, stream: interceptStream)
  629. }
  630. let log = Logger(label: label)
  631. let testString = "my message is better than yours"
  632. log.critical("\(testString)", metadata: ["a": "a0", "b": "b0"])
  633. log.critical("\(testString)", metadata: ["b": "b1", "a": "a1"])
  634. XCTAssertEqual(interceptStream.strings.count, 2)
  635. guard interceptStream.strings.count == 2 else {
  636. XCTFail("Intercepted \(interceptStream.strings.count) logs, expected 2")
  637. return
  638. }
  639. XCTAssert(interceptStream.strings[0].contains("a=a0 b=b0"))
  640. XCTAssert(interceptStream.strings[1].contains("a=a1 b=b1"))
  641. }
  642. func testStdioOutputStreamWrite() {
  643. self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in
  644. let logStream = StdioOutputStream(file: writeFD, flushMode: .always)
  645. LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) }
  646. let log = Logger(label: "test")
  647. let testString = "hello\u{0} world"
  648. log.critical("\(testString)")
  649. let size = read(readFD, readBuffer, 256)
  650. let output = String(decoding: UnsafeRawBufferPointer(start: UnsafeRawPointer(readBuffer), count: numericCast(size)), as: UTF8.self)
  651. let messageSucceeded = output.trimmingCharacters(in: .whitespacesAndNewlines).hasSuffix(testString)
  652. XCTAssertTrue(messageSucceeded)
  653. }
  654. }
  655. func testStdioOutputStreamFlush() {
  656. // flush on every statement
  657. self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in
  658. let logStream = StdioOutputStream(file: writeFD, flushMode: .always)
  659. LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) }
  660. Logger(label: "test").critical("test")
  661. let size = read(readFD, readBuffer, 256)
  662. XCTAssertGreaterThan(size, -1, "expected flush")
  663. logStream.flush()
  664. let size2 = read(readFD, readBuffer, 256)
  665. XCTAssertEqual(size2, -1, "expected no flush")
  666. }
  667. // default flushing
  668. self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in
  669. let logStream = StdioOutputStream(file: writeFD, flushMode: .undefined)
  670. LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) }
  671. Logger(label: "test").critical("test")
  672. let size = read(readFD, readBuffer, 256)
  673. XCTAssertEqual(size, -1, "expected no flush")
  674. logStream.flush()
  675. let size2 = read(readFD, readBuffer, 256)
  676. XCTAssertGreaterThan(size2, -1, "expected flush")
  677. }
  678. }
  679. func withWriteReadFDsAndReadBuffer(_ body: (CFilePointer, CInt, UnsafeMutablePointer<Int8>) -> Void) {
  680. var fds: [Int32] = [-1, -1]
  681. #if os(Windows)
  682. fds.withUnsafeMutableBufferPointer {
  683. let err = _pipe($0.baseAddress, 256, _O_BINARY)
  684. XCTAssertEqual(err, 0, "_pipe failed \(err)")
  685. }
  686. #else
  687. fds.withUnsafeMutableBufferPointer { ptr in
  688. let err = pipe(ptr.baseAddress!)
  689. XCTAssertEqual(err, 0, "pipe failed \(err)")
  690. }
  691. #endif
  692. let writeFD = fdopen(fds[1], "w")
  693. let writeBuffer = UnsafeMutablePointer<Int8>.allocate(capacity: 256)
  694. defer {
  695. writeBuffer.deinitialize(count: 256)
  696. writeBuffer.deallocate()
  697. }
  698. var err = setvbuf(writeFD, writeBuffer, _IOFBF, 256)
  699. XCTAssertEqual(err, 0, "setvbuf failed \(err)")
  700. let readFD = fds[0]
  701. #if os(Windows)
  702. let hPipe: HANDLE = HANDLE(bitPattern: _get_osfhandle(readFD))!
  703. XCTAssertFalse(hPipe == INVALID_HANDLE_VALUE)
  704. var dwMode: DWORD = DWORD(PIPE_NOWAIT)
  705. let bSucceeded = SetNamedPipeHandleState(hPipe, &dwMode, nil, nil)
  706. XCTAssertTrue(bSucceeded)
  707. #else
  708. err = fcntl(readFD, F_SETFL, fcntl(readFD, F_GETFL) | O_NONBLOCK)
  709. XCTAssertEqual(err, 0, "fcntl failed \(err)")
  710. #endif
  711. let readBuffer = UnsafeMutablePointer<Int8>.allocate(capacity: 256)
  712. defer {
  713. readBuffer.deinitialize(count: 256)
  714. readBuffer.deallocate()
  715. }
  716. // the actual test
  717. body(writeFD!, readFD, readBuffer)
  718. fds.forEach { close($0) }
  719. }
  720. func testOverloadingError() {
  721. struct Dummy: Error, LocalizedError {
  722. var errorDescription: String? {
  723. return "errorDescription"
  724. }
  725. }
  726. // bootstrap with our test logging impl
  727. let logging = TestLogging()
  728. LoggingSystem.bootstrapInternal(logging.make)
  729. var logger = Logger(label: "test")
  730. logger.logLevel = .error
  731. logger.error(error: Dummy())
  732. logging.history.assertExist(level: .error, message: "errorDescription")
  733. }
  734. }
  735. extension Logger {
  736. #if compiler(>=5.3)
  737. public func error(error: Error,
  738. metadata: @autoclosure () -> Logger.Metadata? = nil,
  739. file: String = #fileID, function: String = #function, line: UInt = #line) {
  740. self.error("\(error.localizedDescription)", metadata: metadata(), file: file, function: function, line: line)
  741. }
  742. #else
  743. public func error(error: Error,
  744. metadata: @autoclosure () -> Logger.Metadata? = nil,
  745. file: String = #file, function: String = #function, line: UInt = #line) {
  746. self.error("\(error.localizedDescription)", metadata: metadata(), file: file, function: function, line: line)
  747. }
  748. #endif
  749. }
  750. // Sendable
  751. #if compiler(>=5.6)
  752. // used to test logging metadata which requires Sendable conformance
  753. // @unchecked Sendable since manages it own state
  754. extension LoggingTest.LazyMetadataBox: @unchecked Sendable {}
  755. // used to test logging stream which requires Sendable conformance
  756. // @unchecked Sendable since manages it own state
  757. extension LoggingTest.InterceptStream: @unchecked Sendable {}
  758. #endif