Merge pull request #254 from algorandfoundation/logging

feat: Added better control over logging and less verbose default logging

docs/README.md

@@ -84,9 +84,9 @@ export type Logger = {
 }
 ```
 
-Note: this interface type is directly compatible with [Winston](https://github.com/winstonjs/winston).
+Note: this interface type is directly compatible with [Winston](https://github.com/winstonjs/winston) so you should be able to pass AlgoKit a Winston logger.
 
-By default, the [`ConsoleLogger`](./code/modules/types_logging.md#consolelogger) is set as the logger, which will send log messages to the various `console.*` methods. There is also a [`NullLogger`](./code/modules/types_logging.md#nulllogger) if you want to disable logging.
+By default, the [`consoleLogger`](./code/modules/types_logging.md#consolelogger) is set as the logger, which will send log messages to the various `console.*` methods for all logs apart from verbose logs. There is also a [`nullLogger`](./code/modules/types_logging.md#nulllogger) if you want to disable logging, or various leveled console loggers: [`verboseConsoleLogger`](./code/modules/types_logging.md#verboseconsolelogger) (also outputs verbose logs), [`infoConsoleLogger`](./code/modules/types_logging.md#infoconsolelogger) (only outputs info, warning and error logs), [`warningConsoleLogger`](./code/modules/types_logging.md#warningconsolelogger) (only outputs warning and error logs).
 
 If you want to override the logger you can use the following:
 

docs/code/modules/index.md

@@ -349,7 +349,7 @@ the estimated rate.
 
 #### Defined in
 
-[src/transaction/transaction.ts:757](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L757)
+[src/transaction/transaction.ts:764](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L764)
 
 ___
 
@@ -405,7 +405,7 @@ Allows for control of fees on a `Transaction` or `SuggestedParams` object
 
 #### Defined in
 
-[src/transaction/transaction.ts:780](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L780)
+[src/transaction/transaction.ts:787](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L787)
 
 ___
 
@@ -1477,7 +1477,7 @@ The array of transactions with signers
 
 #### Defined in
 
-[src/transaction/transaction.ts:812](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L812)
+[src/transaction/transaction.ts:819](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L819)
 
 ___
 
@@ -1810,7 +1810,7 @@ The suggested transaction parameters
 
 #### Defined in
 
-[src/transaction/transaction.ts:803](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L803)
+[src/transaction/transaction.ts:810](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L810)
 
 ___
 
@@ -2145,7 +2145,7 @@ The dryrun result
 
 #### Defined in
 
-[src/transaction/transaction.ts:637](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L637)
+[src/transaction/transaction.ts:644](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L644)
 
 ___
 
@@ -2461,7 +2461,7 @@ An object with transaction IDs, transactions, group transaction ID (`groupTransa
 
 #### Defined in
 
-[src/transaction/transaction.ts:655](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L655)
+[src/transaction/transaction.ts:662](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L662)
 
 ___
 
@@ -2740,4 +2740,4 @@ Throws an error if the transaction is not confirmed or rejected in the next `tim
 
 #### Defined in
 
-[src/transaction/transaction.ts:700](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L700)
+[src/transaction/transaction.ts:707](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/transaction/transaction.ts#L707)

docs/code/modules/types_logging.md

@@ -11,7 +11,10 @@
 ### Variables
 
 - [consoleLogger](types_logging.md#consolelogger)
+- [infoConsoleLogger](types_logging.md#infoconsolelogger)
 - [nullLogger](types_logging.md#nulllogger)
+- [verboseConsoleLogger](types_logging.md#verboseconsolelogger)
+- [warningConsoleLogger](types_logging.md#warningconsolelogger)
 
 ## Type Aliases
 
@@ -49,6 +52,16 @@ A logger implementation that writes to console
 
 ___
 
+### infoConsoleLogger
+
+• `Const` **infoConsoleLogger**: [`Logger`](types_logging.md#logger)
+
+#### Defined in
+
+[src/types/logging.ts:22](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/types/logging.ts#L22)
+
+___
+
 ### nullLogger
 
 • `Const` **nullLogger**: [`Logger`](types_logging.md#logger)
@@ -57,4 +70,24 @@ A logger implementation that does nothing
 
 #### Defined in
 
-[src/types/logging.ts:23](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/types/logging.ts#L23)
+[src/types/logging.ts:47](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/types/logging.ts#L47)
+
+___
+
+### verboseConsoleLogger
+
+• `Const` **verboseConsoleLogger**: [`Logger`](types_logging.md#logger)
+
+#### Defined in
+
+[src/types/logging.ts:30](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/types/logging.ts#L30)
+
+___
+
+### warningConsoleLogger
+
+• `Const` **warningConsoleLogger**: [`Logger`](types_logging.md#logger)
+
+#### Defined in
+
+[src/types/logging.ts:38](https://github.com/algorandfoundation/algokit-utils-ts/blob/main/src/types/logging.ts#L38)

src/__snapshots__/app-deploy.spec.ts.snap

@@ -5,7 +5,7 @@ exports[`deploy-app Deploy append for schema broken app if onSchemaBreak = Appen
 INFO: Existing app test found by creator ACCOUNT_1, with app id APP_1 and version 1.0.
 WARN: Detected a breaking app schema change in app APP_1: | [{"from":{"global":{"numUint":3,"numByteSlice":2,"attribute_map":{"numUint":"num-uint","numByteSlice":"num-byte-slice"}},"local":{"numUint":2,"numByteSlice":2,"attribute_map":{"numUint":"num-uint","numByteSlice":"num-byte-slice"}}},"to":{"global":{"numUint":3,"numByteSlice":3,"attribute_map":{"numUint":"num-uint","numByteSlice":"num-byte-slice"}},"local":{"numUint":2,"numByteSlice":2,"attribute_map":{"numUint":"num-uint","numByteSlice":"num-byte-slice"}}}}]
 INFO: onSchemaBreak=AppendApp, will attempt to create a new app
-INFO: Sent transaction ID TXID_2 appl from ACCOUNT_1
+VERBOSE: Sent transaction ID TXID_2 appl from ACCOUNT_1
 DEBUG: Created app APP_2 from creator ACCOUNT_1"
 `;
 
@@ -14,7 +14,7 @@ exports[`deploy-app Deploy append for update app if onUpdate = AppendApp 1`] = `
 INFO: Existing app test found by creator ACCOUNT_1, with app id APP_1 and version 1.0.
 INFO: Detected a TEAL update in app APP_1 for creator ACCOUNT_1
 INFO: onUpdate=AppendApp, will attempt to create a new app
-INFO: Sent transaction ID TXID_2 appl from ACCOUNT_1
+VERBOSE: Sent transaction ID TXID_2 appl from ACCOUNT_1
 DEBUG: Created app APP_2 from creator ACCOUNT_1"
 `;
 
@@ -25,7 +25,7 @@ INFO: Detected a TEAL update in app APP_1 for creator ACCOUNT_1
 WARN: App is not deletable and onUpdate=ReplaceApp, will attempt to create new app and delete old app, delete will most likely fail
 INFO: Deploying a new test app for ACCOUNT_1; deploying app with version 2.0.
 WARN: Deleting existing test app with id APP_1 from ACCOUNT_1 account.
-INFO: Received error executing Atomic Transaction Composer, for more information enable the debug flag"
+ERROR: Received error executing Atomic Transaction Composer, for more information enable the debug flag | [{"response":{"body":{"data":{"app-index":APP_1,"eval-states":[{},{"stack":[0]}],"group-index":1,"pc":994},"message":"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=994. Details: app=APP_1, pc=994, opcodes=assert; intc 5 // 0; assert"},"status":400,"text":"{\\"data\\":{\\"app-index\\":APP_1,\\"eval-states\\":[{},{\\"stack\\":[0]}],\\"group-index\\":1,\\"pc\\":994},\\"message\\":\\"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=994. Details: app=APP_1, pc=994, opcodes=assert; intc 5 // 0; assert\\"}\\n","ok":false},"name":"URLTokenBaseHTTPError","status":400}]"
 `;
 
 exports[`deploy-app Deploy failure for replacement of schema broken app fails if onSchemaBreak = Fail 1`] = `
@@ -43,7 +43,7 @@ INFO: Detected a TEAL update in app APP_1 for creator ACCOUNT_1"
 exports[`deploy-app Deploy new app 1`] = `
 "INFO: Idempotently deploying app "test" from creator ACCOUNT_1 using 11890 bytes of teal code and 39 bytes of teal code
 INFO: App test not found in apps created by ACCOUNT_1; deploying app with version 1.0.
-INFO: Sent transaction ID TXID_1 appl from ACCOUNT_1
+VERBOSE: Sent transaction ID TXID_1 appl from ACCOUNT_1
 DEBUG: Created app APP_1 from creator ACCOUNT_1"
 `;
 
@@ -74,7 +74,7 @@ WARN: Detected a breaking app schema change in app APP_1: | [{"from":{"global":{
 INFO: App is not deletable but onSchemaBreak=ReplaceApp, will attempt to delete app, delete will most likely fail
 INFO: Deploying a new test app for ACCOUNT_1; deploying app with version 2.0.
 WARN: Deleting existing test app with id APP_1 from ACCOUNT_1 account.
-INFO: Received error executing Atomic Transaction Composer, for more information enable the debug flag"
+ERROR: Received error executing Atomic Transaction Composer, for more information enable the debug flag | [{"response":{"body":{"data":{"app-index":APP_1,"eval-states":[{},{"stack":[0]}],"group-index":1,"pc":994},"message":"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=994. Details: app=APP_1, pc=994, opcodes=assert; intc 5 // 0; assert"},"status":400,"text":"{\\"data\\":{\\"app-index\\":APP_1,\\"eval-states\\":[{},{\\"stack\\":[0]}],\\"group-index\\":1,\\"pc\\":994},\\"message\\":\\"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=994. Details: app=APP_1, pc=994, opcodes=assert; intc 5 // 0; assert\\"}\\n","ok":false},"name":"URLTokenBaseHTTPError","status":400}]"
 `;
 
 exports[`deploy-app Deploy update to immutable updated app fails 1`] = `
@@ -93,7 +93,7 @@ INFO: Detected a TEAL update in app APP_1 for creator ACCOUNT_1
 INFO: App is updatable and onUpdate=UpdateApp, updating app...
 INFO: Updating existing test app for ACCOUNT_1 to version 2.0.
 DEBUG: Updating app APP_1
-INFO: Sent transaction ID TXID_2 appl from ACCOUNT_1"
+VERBOSE: Sent transaction ID TXID_2 appl from ACCOUNT_1"
 `;
 
 exports[`deploy-app Do nothing if deploying app with no changes 1`] = `

src/app-deploy.spec.ts

@@ -5,6 +5,7 @@ import * as algokit from '.'
 import { getTestingAppCreateParams, getTestingAppDeployParams } from '../tests/example-contracts/testing-app/contract'
 import { algoKitLogCaptureFixture, algorandFixture } from './testing'
 import { AppDeployMetadata, AppDeploymentParams } from './types/app'
+import { LogicError } from './types/logic-error'
 
 describe('deploy-app', () => {
   const localnet = algorandFixture()
@@ -203,16 +204,23 @@ describe('deploy-app', () => {
       codeInjectionValue: 2,
       onUpdate: 'update',
     })
-    await expect(() => algokit.deployApp(deployment2, algod, indexer)).rejects.toThrow(/logic eval error: assert failed/)
 
-    invariant('transaction' in result1)
-    expect(
-      logging.testLogger.getLogSnapshot({
-        accounts: [testAccount],
-        transactions: [result1.transaction],
-        apps: [result1.appId],
-      }),
-    ).toMatchSnapshot()
+    try {
+      await algokit.deployApp(deployment2, algod, indexer)
+      invariant(false)
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    } catch (e: any) {
+      expect(e.message).toMatch(/logic eval error: assert failed/)
+      const logicError = LogicError.parseLogicError(e)
+      invariant('transaction' in result1)
+      expect(
+        logging.testLogger.getLogSnapshot({
+          accounts: [testAccount],
+          transactions: [result1.transaction, logicError!.txId],
+          apps: [result1.appId],
+        }),
+      ).toMatchSnapshot()
+    }
   })
 
   test('Deploy failure for updated app fails if onupdate = Fail', async () => {
@@ -310,16 +318,22 @@ describe('deploy-app', () => {
       onUpdate: 'replace',
     })) as AppDeploymentParams
 
-    await expect(() => algokit.deployApp(deployment2, algod, indexer)).rejects.toThrow(/logic eval error: assert failed/)
-
-    invariant('transaction' in result1)
-    expect(
-      logging.testLogger.getLogSnapshot({
-        accounts: [testAccount],
-        transactions: [result1.transaction],
-        apps: [result1.appId],
-      }),
-    ).toMatchSnapshot()
+    try {
+      await algokit.deployApp(deployment2, algod, indexer)
+      invariant(false)
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    } catch (e: any) {
+      expect(e.message).toMatch(/logic eval error: assert failed/)
+      const logicError = LogicError.parseLogicError(e)
+      invariant('transaction' in result1)
+      expect(
+        logging.testLogger.getLogSnapshot({
+          accounts: [testAccount],
+          transactions: [result1.transaction, logicError!.txId],
+          apps: [result1.appId],
+        }),
+      ).toMatchSnapshot()
+    }
   })
 
   test('Deploy replacement of deletable schema broken app', async () => {
@@ -384,16 +398,22 @@ describe('deploy-app', () => {
       onSchemaBreak: 'replace',
     })) as AppDeploymentParams
 
-    await expect(() => algokit.deployApp(deployment2, algod, indexer)).rejects.toThrow(/logic eval error: assert failed/)
-
-    invariant('transaction' in result1)
-    expect(
-      logging.testLogger.getLogSnapshot({
-        accounts: [testAccount],
-        transactions: [result1.transaction],
-        apps: [result1.appId],
-      }),
-    ).toMatchSnapshot()
+    try {
+      await algokit.deployApp(deployment2, algod, indexer)
+      invariant(false)
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    } catch (e: any) {
+      expect(e.message).toMatch(/logic eval error: assert failed/)
+      const logicError = LogicError.parseLogicError(e)
+      invariant('transaction' in result1)
+      expect(
+        logging.testLogger.getLogSnapshot({
+          accounts: [testAccount],
+          transactions: [result1.transaction, logicError!.txId],
+          apps: [result1.appId],
+        }),
+      ).toMatchSnapshot()
+    }
   })
 
   test('Deploy failure for replacement of schema broken app fails if onSchemaBreak = Fail', async () => {

src/transaction/transaction.ts

@@ -222,7 +222,7 @@ export const sendTransaction = async function (
 
   await algod.sendRawTransaction(signedTransaction).do()
 
-  Config.getLogger(suppressLog).info(`Sent transaction ID ${txnToSend.txID()} ${txnToSend.type} from ${getSenderAddress(from)}`)
+  Config.getLogger(suppressLog).verbose(`Sent transaction ID ${txnToSend.txID()} ${txnToSend.type} from ${getSenderAddress(from)}`)
 
   let confirmation: modelsv2.PendingTransactionResponse | undefined = undefined
   if (!skipWaiting) {
@@ -535,7 +535,7 @@ export const sendAtomicTransactionComposer = async function (atcSend: AtomicTran
     let groupId: string | undefined = undefined
     if (transactionsToSend.length > 1) {
       groupId = transactionsToSend[0].group ? Buffer.from(transactionsToSend[0].group).toString('base64') : ''
-      Config.getLogger(sendParams?.suppressLog).info(`Sending group of ${transactionsToSend.length} transactions (${groupId})`, {
+      Config.getLogger(sendParams?.suppressLog).verbose(`Sending group of ${transactionsToSend.length} transactions (${groupId})`, {
         transactionsToSend,
       })
 
@@ -557,9 +557,11 @@ export const sendAtomicTransactionComposer = async function (atcSend: AtomicTran
     const result = await atc.execute(algod, sendParams?.maxRoundsToWaitForConfirmation ?? 5)
 
     if (transactionsToSend.length > 1) {
-      Config.getLogger(sendParams?.suppressLog).info(`Group transaction (${groupId}) sent with ${transactionsToSend.length} transactions`)
+      Config.getLogger(sendParams?.suppressLog).verbose(
+        `Group transaction (${groupId}) sent with ${transactionsToSend.length} transactions`,
+      )
     } else {
-      Config.getLogger(sendParams?.suppressLog).info(
+      Config.getLogger(sendParams?.suppressLog).verbose(
         `Sent transaction ID ${transactionsToSend[0].txID()} ${transactionsToSend[0].type} from ${algosdk.encodeAddress(
           transactionsToSend[0].from.publicKey,
         )}`,
@@ -591,11 +593,14 @@ export const sendAtomicTransactionComposer = async function (atcSend: AtomicTran
     } as SendAtomicTransactionComposerResults
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
   } catch (e: any) {
-    Config.logger.info('Received error executing Atomic Transaction Composer, for more information enable the debug flag')
+    // Remove headers as it doesn't have anything useful.
+    delete e.response?.headers
+
     if (Config.debug && typeof e === 'object') {
       e.traces = []
-      Config.logger.debug(
+      Config.logger.error(
         'Received error executing Atomic Transaction Composer and debug flag enabled; attempting simulation to get more information',
+        e,
       )
       let simulate = undefined
       if (Config.debug && Config.projectRoot && !Config.traceAll) {
@@ -623,6 +628,8 @@ export const sendAtomicTransactionComposer = async function (atcSend: AtomicTran
           })
         }
       }
+    } else {
+      Config.logger.error('Received error executing Atomic Transaction Composer, for more information enable the debug flag', e)
     }
     throw e
   }

src/types/__snapshots__/app-client.spec.ts.snap

@@ -3,8 +3,7 @@
 exports[`application-client Errors Display nice error messages when there is a logic error 2`] = `
 "INFO: Idempotently deploying app "TestingApp" from creator ACCOUNT_1 using 1498 bytes of teal code and 4 bytes of teal code
 INFO: App TestingApp not found in apps created by ACCOUNT_1; deploying app with version 1.0.
-INFO: Sent transaction ID TXID_1 appl from ACCOUNT_1
+VERBOSE: Sent transaction ID TXID_1 appl from ACCOUNT_1
 DEBUG: Created app APP_1 from creator ACCOUNT_1
-INFO: Received error executing Atomic Transaction Composer, for more information enable the debug flag
-DEBUG: Received error executing Atomic Transaction Composer and debug flag enabled; attempting simulation to get more information"
+ERROR: Received error executing Atomic Transaction Composer and debug flag enabled; attempting simulation to get more information | [{"response":{"body":{"data":{"app-index":APP_1,"eval-states":[{"stack":[0]}],"group-index":0,"pc":885},"message":"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=885. Details: app=APP_1, pc=885, opcodes=proto 0 0; intc_0 // 0; assert"},"status":400,"text":"{\\"data\\":{\\"app-index\\":APP_1,\\"eval-states\\":[{\\"stack\\":[0]}],\\"group-index\\":0,\\"pc\\":885},\\"message\\":\\"TransactionPool.Remember: transaction TXID_2: logic eval error: assert failed pc=885. Details: app=APP_1, pc=885, opcodes=proto 0 0; intc_0 // 0; assert\\"}\\n","ok":false},"name":"URLTokenBaseHTTPError","status":400,"traces":[]}]"
 `;

src/types/app-client.spec.ts

@@ -733,14 +733,14 @@ describe('application-client', () => {
           create_8:"
         `)
         expect(e.led.traces.length).toBe(1)
+        expect(
+          logging.testLogger.getLogSnapshot({
+            accounts: [testAccount],
+            transactions: app.operationPerformed === 'create' ? [app.transaction, e.led.txId] : [],
+            apps: [app.appId],
+          }),
+        ).toMatchSnapshot()
       }
-      expect(
-        logging.testLogger.getLogSnapshot({
-          accounts: [testAccount],
-          transactions: app.operationPerformed === 'create' ? [app.transaction] : [],
-          apps: [app.appId],
-        }),
-      ).toMatchSnapshot()
     })
   })