stellarsaur
commented
11 months ago From a user perspective, I think this should be logged at the debug level by specifying --verbose, especially for contracts where the output would be much longer.
Open leighmcculloch opened 1 year ago
stellarsaur
commented
11 months ago From a user perspective, I think this should be logged at the debug level by specifying --verbose, especially for contracts where the output would be much longer.
leighmcculloch
commented
8 months ago Doing a recent test and this still appears to be the case, especially on error.
It's pretty difficult to read the meaningful diagnostic logs on an invocation that has failed.
Example:
$ soroban contract invoke --id CBMISTGN3AF5RESQ3ZKLUIMJ22X4MC7ARBQCC3IWINUXDXYJKH4QNMQX --instructions 1 -- increment2024-03-07T03:55:33.366782Z ERROR soroban_rpc: GetTransactionResponse {
status: "FAILED",
envelope: Some(
Tx(
TransactionV1Envelope {
tx: Transaction {
source_account: Ed25519(
Uint256(4e1e0bcfe8aa0a105863702f8512b1c43980ef208f40d6b0d1fdf6d16903ae75),
),
fee: 56113,
seq_num: SequenceNumber(
1421634174980,
),
cond: None,
memo: None,
operations: VecM(
[
Operation {
source_account: None,
body: InvokeHostFunction(
InvokeHostFunctionOp {
host_function: InvokeContract(
InvokeContractArgs {
contract_address: Contract(
Hash(58894ccdd80bd89250de54ba2189d6afc60be08860216d16436971df0951f906),
),
function_name: ScSymbol(
StringM(increment),
),
args: VecM(
[],
),
},
),
auth: VecM(
[],
),
},
),
},
],
),
ext: V1(
SorobanTransactionData {
ext: V0,
resources: SorobanResources {
footprint: LedgerFootprint {
read_only: VecM(
[
ContractCode(
LedgerKeyContractCode {
hash: Hash(1d4a2ca9a32c56b82f67e97aa315f917d63e408d4fff6da381ced0cb606dcbdb),
},
),
],
),
read_write: VecM(
[
ContractData(
LedgerKeyContractData {
contract: Contract(
Hash(58894ccdd80bd89250de54ba2189d6afc60be08860216d16436971df0951f906),
),
key: LedgerKeyContractInstance,
durability: Persistent,
},
),
],
),
},
instructions: 1,
read_bytes: 880,
write_bytes: 132,
},
resource_fee: 48694,
},
),
},
signatures: VecM(
[
DecoratedSignature {
hint: SignatureHint(6903ae75),
signature: Signature(
BytesM(da1f1cf61bb5d86ba5859c80f175d7bb09d9ae591edab7f567d1cd725863579de6d36197085193f07f5c7b9436823fc916486923054bcc6776694788ddf3080f),
),
},
],
),
},
),
),
result: Some(
TransactionResult {
fee_charged: 34813,
result: TxFailed(
VecM(
[
OpInner(
InvokeHostFunction(
ResourceLimitExceeded,
),
),
],
),
),
ext: V0,
},
),
result_meta: Some(
V3(
TransactionMetaV3 {
ext: V0,
tx_changes_before: LedgerEntryChanges(
VecM(
[
State(
LedgerEntry {
last_modified_ledger_seq: 1765,
data: Account(
AccountEntry {
account_id: AccountId(
PublicKeyTypeEd25519(
Uint256(4e1e0bcfe8aa0a105863702f8512b1c43980ef208f40d6b0d1fdf6d16903ae75),
),
),
balance: 99998521152,
seq_num: SequenceNumber(
1421634174979,
),
num_sub_entries: 0,
inflation_dest: None,
flags: 0,
home_domain: String32(
StringM(),
),
thresholds: Thresholds(01000000),
signers: VecM(
[],
),
ext: V1(
AccountEntryExtensionV1 {
liabilities: Liabilities {
buying: 0,
selling: 0,
},
ext: V2(
AccountEntryExtensionV2 {
num_sponsored: 0,
num_sponsoring: 0,
signer_sponsoring_i_ds: VecM(
[],
),
ext: V3(
AccountEntryExtensionV3 {
ext: V0,
seq_ledger: 1738,
seq_time: TimePoint(
1709783705,
),
},
),
},
),
},
),
},
),
ext: V0,
},
),
Updated(
LedgerEntry {
last_modified_ledger_seq: 1765,
data: Account(
AccountEntry {
account_id: AccountId(
PublicKeyTypeEd25519(
Uint256(4e1e0bcfe8aa0a105863702f8512b1c43980ef208f40d6b0d1fdf6d16903ae75),
),
),
balance: 99998521152,
seq_num: SequenceNumber(
1421634174980,
),
num_sub_entries: 0,
inflation_dest: None,
flags: 0,
home_domain: String32(
StringM(),
),
thresholds: Thresholds(01000000),
signers: VecM(
[],
),
ext: V1(
AccountEntryExtensionV1 {
liabilities: Liabilities {
buying: 0,
selling: 0,
},
ext: V2(
AccountEntryExtensionV2 {
num_sponsored: 0,
num_sponsoring: 0,
signer_sponsoring_i_ds: VecM(
[],
),
ext: V3(
AccountEntryExtensionV3 {
ext: V0,
seq_ledger: 1765,
seq_time: TimePoint(
1709783732,
),
},
),
},
),
},
),
},
),
ext: V0,
},
),
],
),
),
operations: VecM(
[],
),
tx_changes_after: LedgerEntryChanges(
VecM(
[
State(
LedgerEntry {
last_modified_ledger_seq: 1765,
data: Account(
AccountEntry {
account_id: AccountId(
PublicKeyTypeEd25519(
Uint256(4e1e0bcfe8aa0a105863702f8512b1c43980ef208f40d6b0d1fdf6d16903ae75),
),
),
balance: 99998521152,
seq_num: SequenceNumber(
1421634174980,
),
num_sub_entries: 0,
inflation_dest: None,
flags: 0,
home_domain: String32(
StringM(),
),
thresholds: Thresholds(01000000),
signers: VecM(
[],
),
ext: V1(
AccountEntryExtensionV1 {
liabilities: Liabilities {
buying: 0,
selling: 0,
},
ext: V2(
AccountEntryExtensionV2 {
num_sponsored: 0,
num_sponsoring: 0,
signer_sponsoring_i_ds: VecM(
[],
),
ext: V3(
AccountEntryExtensionV3 {
ext: V0,
seq_ledger: 1765,
seq_time: TimePoint(
1709783732,
),
},
),
},
),
},
),
},
),
ext: V0,
},
),
Updated(
LedgerEntry {
last_modified_ledger_seq: 1765,
data: Account(
AccountEntry {
account_id: AccountId(
PublicKeyTypeEd25519(
Uint256(4e1e0bcfe8aa0a105863702f8512b1c43980ef208f40d6b0d1fdf6d16903ae75),
),
),
balance: 99998535133,
seq_num: SequenceNumber(
1421634174980,
),
num_sub_entries: 0,
inflation_dest: None,
flags: 0,
home_domain: String32(
StringM(),
),
thresholds: Thresholds(01000000),
signers: VecM(
[],
),
ext: V1(
AccountEntryExtensionV1 {
liabilities: Liabilities {
buying: 0,
selling: 0,
},
ext: V2(
AccountEntryExtensionV2 {
num_sponsored: 0,
num_sponsoring: 0,
signer_sponsoring_i_ds: VecM(
[],
),
ext: V3(
AccountEntryExtensionV3 {
ext: V0,
seq_ledger: 1765,
seq_time: TimePoint(
1709783732,
),
},
),
},
),
},
),
},
),
ext: V0,
},
),
],
),
),
soroban_meta: Some(
SorobanTransactionMeta {
ext: V0,
events: VecM(
[],
),
return_value: Bool(
false,
),
diagnostic_events: VecM(
[
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(host_fn_failed),
),
),
Error(
Budget(
ExceededLimit,
),
),
],
),
data: Void,
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(read_entry),
),
),
],
),
data: U64(
2,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(write_entry),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(ledger_read_byte),
),
),
],
),
data: U64(
880,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(ledger_write_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(read_key_byte),
),
),
],
),
data: U64(
84,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(write_key_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(read_data_byte),
),
),
],
),
data: U64(
132,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(write_data_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(read_code_byte),
),
),
],
),
data: U64(
748,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(write_code_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(emit_event),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(emit_event_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(cpu_insn),
),
),
],
),
data: U64(
3880,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(mem_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(invoke_time_nsecs),
),
),
],
),
data: U64(
1209,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(max_rw_key_byte),
),
),
],
),
data: U64(
48,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(max_rw_data_byte),
),
),
],
),
data: U64(
132,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(max_rw_code_byte),
),
),
],
),
data: U64(
748,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(core_metrics),
),
),
Symbol(
ScSymbol(
StringM(max_emit_event_byte),
),
),
],
),
data: U64(
0,
),
},
),
},
},
DiagnosticEvent {
in_successful_contract_call: false,
event: ContractEvent {
ext: V0,
contract_id: None,
type_: Diagnostic,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(error),
),
),
Error(
Budget(
ExceededLimit,
),
),
],
),
data: Vec(
Some(
ScVec(
VecM(
[
String(
ScString(
StringM(operation instructions exceeds amount specified),
),
),
U64(
3880,
),
U64(
1,
),
],
),
),
),
),
},
),
},
},
],
),
},
),
},
),
),
}
error: transaction submission failed: Some(
TransactionResult {
fee_charged: 34813,
result: TxFailed(
VecM(
[
OpInner(
InvokeHostFunction(
ResourceLimitExceeded,
),
),
],
),
),
ext: V0,
},
)This is also still the case in successful invocations:
$ soroban contract invoke --id CDLZFC3SYJYDZT7K67VZ75HPJVIEUVNIXF47ZG2FB2RMQQVU2HHGCYSC -- transfer --from GBTBT26GIZWQO2FRPU6NCMTVHX4F3P2KYZWVZDNRFYIPAV323ODV7HZV --to CDZMTQGMYJC2MGF5WOYJXDUSVTYIYCW4FK5HXJAO5NCWABXL4J5U6XSA --amount 1
2024-03-21T04:36:48.081460Z INFO soroban_cli::log::diagnostic_event: 0: DiagnosticEvent {
in_successful_contract_call: true,
event: ContractEvent {
ext: V0,
contract_id: Some(
Hash(d7928b72c2703ccfeaf7eb9ff4ef4d504a55a8b979fc9b450ea2c842b4d1ce61),
),
type_: Contract,
body: V0(
ContractEventV0 {
topics: VecM(
[
Symbol(
ScSymbol(
StringM(transfer),
),
),
Address(
Account(
AccountId(
PublicKeyTypeEd25519(
Uint256(6619ebc6466d0768b17d3cd132753df85dbf4ac66d5c8db12e10f0577adb875f),
),
),
),
),
Address(
Contract(
Hash(f2c9c0ccc245a618bdb3b09b8e92acf08c0adc2aba7ba40eeb456006ebe27b4f),
),
),
String(
ScString(
StringM(native),
),
),
],
),
data: I128(
Int128Parts {
hi: 0,
lo: 1,
},
),
},
),
},
}I think we should change this output to be the JSON representation, which would look like this:
{
"ext": "v0",
"contract_id": "d7928b72c2703ccfeaf7eb9ff4ef4d504a55a8b979fc9b450ea2c842b4d1ce61",
"type_": "contract",
"body": {
"v0": {
"topics": [
{
"symbol": "transfer"
},
{
"address": "GBTBT26GIZWQO2FRPU6NCMTVHX4F3P2KYZWVZDNRFYIPAV323ODV7HZV"
},
{
"address": "CDZMTQGMYJC2MGF5WOYJXDUSVTYIYCW4FK5HXJAO5NCWABXL4J5U6XSA"
},
{
"string": "native"
}
],
"data": {
"i128": {
"hi": 0,
"lo": 1
}
}
}
}
}
What version are you using?
What did you do?
What did you expect to see?
What did you see instead?
Discussion
This seems like possibly a bug, such as we're logging something at the wrong level, or not distinguishing between contract events vs host events when deciding to log at the info level.
However, this might also not be a bug and it might be working as intended. I'm not sure.