Opcode: log by shiqizng · Pull Request #2529 · algorand/go-algorand

shiqizng · 2021-07-13T15:21:39Z

This PR adds a new opcode log. It takes one "bytes" stack argument. It can be called up to 32 times in a program, and log up to a total of 1k bytes.

… opcode/log

jannotti

I'd like to see some tests that contain multiple calls to log

runvnc · 2021-07-13T16:50:58Z

Hello, this is really great. I have been doing my own "log()" in Tealang using get, put and concat. One thing I wonder though, why is it necessary to limit to 8 times, rather than using the existing cost system?

jannotti · 2021-07-13T17:45:09Z

Hello, this is really great. I have been doing my own "log()" in Tealang using get, put and concat. One thing I wonder though, why is it necessary to limit to 8 times, rather than using the existing cost system?

After discussion on Discord, we've decided that allowing 32 calls makes sense, with the 1k limit intact. For posterity - the reason for two such limits is, as with ApplicationArgs, there is additional space overhead associated with each call, so it should not be possible to log 1000 1 byte messages, as that would consume much more than 1k. But 32 should not really make much difference.

codecov-commenter · 2021-07-13T21:21:33Z

Codecov Report

Merging #2529 (f375213) into master (9194dec) will decrease coverage by 0.07%.
The diff coverage is 36.64%.

@@            Coverage Diff             @@
##           master    #2529      +/-   ##
==========================================
- Coverage   47.16%   47.08%   -0.08%     
==========================================
  Files         350      350              
  Lines       55954    56276     +322     
==========================================
+ Hits        26389    26499     +110     
- Misses      26620    26808     +188     
- Partials     2945     2969      +24

Impacted Files	Coverage Δ
config/consensus.go	`84.01% <ø> (ø)`
daemon/algod/api/server/v2/handlers.go	`0.00% <0.00%> (ø)`
daemon/algod/api/server/v2/utils.go	`14.50% <0.00%> (-2.32%)`	⬇️
data/transactions/logic/doc.go	`82.75% <ø> (ø)`
data/transactions/logic/opcodes.go	`96.00% <ø> (ø)`
data/basics/msgp_gen.go	`35.46% <32.80%> (-0.36%)`	⬇️
ledger/applications.go	`54.65% <33.33%> (-1.60%)`	⬇️
daemon/algod/api/server/v2/dryrun.go	`58.99% <66.66%> (+1.61%)`	⬆️
data/transactions/application.go	`64.44% <72.72%> (+2.67%)`	⬆️
data/transactions/logic/eval.go	`90.61% <80.00%> (-0.10%)`	⬇️
... and 11 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9194dec...f375213. Read the comment docs.

jdtzmn

Looks good, just had one question.

winder · 2021-07-14T17:49:38Z

+		runMode:     runModeSignature,
+	}
+
+	failCases := []failCase{failCase0, failCase1, failCase2, failCase3, failCase4, failCase5}


nit: A pattern we use a lot for this is an anonymous struct:

failCases := []struct { source string runMode runMode errContains string } { // cases here. }

jasonpaulos

This looks good! I just left some insignificant comments

jasonpaulos

One small thing I noticed

jasonpaulos · 2021-08-04T14:59:46Z

 					result.LocalDeltas = &localDeltas
 				}
+
+				result.Logs = DeltaLogToLog(delta.Logs)


Actually this function should also convert each basics.LogItem's ID into the actual application ID. I believe it should convert 0 into appIdx (which is guaranteed to be not 0 at this point) and it should error if the input ID is not 0.

algorandskiy · 2021-08-04T14:49:14Z

+	ops, err := logic.AssembleString(`
+#pragma version 5
+int 1
+loop: byte "a"


let's do some more fancy stuff there to ensure log values vary. Something like

dup // copy loop var int 48 // 0x32 -> '0' char + itob // -> char log

I couldn't get the suggested teal code. I did something much simpler instead.

the idea is to use ascii char codes to obtain new char value on each loop iteration.

Actually itob always produces an 8 byte slice. It would be better to so something like:

byte "a" int 0 dup2 getbyte // convert 0th byte of "a" to integer, 97 int 1 + // add 1 setbyte // set 0th byte of "a" to the byte given by the integer on the stack (97 + 1, "b")

algorandskiy · 2021-08-04T15:24:03Z

 	a.Panics(func() { c.DelKey(getRandomAddress(a), aidx, false, key, 0) })
 	a.Panics(func() { c.DelKey(addr, aidx+1, false, key, 0) })
 }
+func TestCowAppendLog(t *testing.T) {


+1, run go fmt

algorandskiy · 2021-08-04T15:36:16Z

+
+	prog := `#pragma version 5
+int 1
+loop: byte "a"


let's check different values

I still want to see logging 32 different values in the test:

int 0 // loop variable loop: dup // copy int 97 // 0x61 'a' + // 97, 98, 99, ... itob // 'a', 'b', 'c', ... log int 1 + dup int 32 < bnz loop

see Jason's note about getbyte above #2529 (comment)

algorandskiy · 2021-08-09T15:26:46Z


+// MaxLogCalls is the largest number of log calls that may appear in
+// an eval delta, used for decoding purposes.
+var MaxLogCalls int


this needs to be const, no need to initialize it checkSetAllocBounds.

Suggested change

var MaxLogCalls int

const MaxLogCalls = 32

checkSetAllocBounds might have a check that the value is not greater than 32 (or 33 as JJ suggested)

algorandskiy · 2021-08-09T15:41:21Z

+	for i, m := range logs {
+		if i == 0 {
+			assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("a")), m.Value)
+		} else if i == 1 {
+			assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("b")), m.Value)
+		} else if i == 2 {
+			assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("c")), m.Value)
+		}
+
+	}


Calculating values looks more maintainable, check below:

Suggested change

for i, m := range logs {

if i == 0 {

assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("a")), m.Value)

} else if i == 1 {

assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("b")), m.Value)

} else if i == 2 {

assert.Equal(t, base64.StdEncoding.EncodeToString([]byte("c")), m.Value)

}

}

for i, m := range logs {

assert.Equal(t, base64.StdEncoding.EncodeToString([]byte(string(rune('a' + i)))), m.Value)

}

If logs are not sorted, use sort.Slice. If logs is map (not sure) then flatten it:

type flog struct { idx int, li LogItem } for k, v := range logs { flatlog = append(flatlog, flog{i, v}) } sort.Slice(flatlog, func(i, j int) {return flatlog[i].idx < flatlog[j].idx})

The order of logs matter, so they should not be sorted before comparison

well ok, then assert.Equal(t, base64.StdEncoding.EncodeToString([]byte(string(rune('a' + i)))), m.Value) will work just fine

algorandskiy · 2021-08-09T15:57:18Z

+	ops, err := logic.AssembleString(`
+#pragma version 5
+int 1
+loop: byte "a"


the idea is to use ascii char codes to obtain new char value on each loop iteration.

algorandskiy

I'll incorporate these MaxLogCalls fixes...

algorandskiy · 2021-08-09T19:19:52Z

+// MaxLogCalls is the highest allowable log messages that may appear in
+// any version, used for decoding purposes. Never decrease this value.
+const MaxLogCalls = 32


Suggested change

// MaxLogCalls is the highest allowable log messages that may appear in

// any version, used for decoding purposes. Never decrease this value.

const MaxLogCalls = 32

// MaxLogCalls is the highest allowable log messages that may appear in

// any version, used for decoding purposes. Never decrease this value.

const MaxEncodedLogCalls = 32

algorandskiy · 2021-08-09T19:20:21Z

+const MaxLogSize = 1024
+
+// MaxLogCalls is the limit of total log calls during a program execution
+const MaxLogCalls = config.MaxLogCalls


Suggested change

const MaxLogCalls = config.MaxLogCalls

const MaxLogCalls = 32

algorandskiy · 2021-08-09T19:21:23Z

+			loglen: 2,
+		},
+		{
+			source: fmt.Sprintf(`%s int 1`, strings.Repeat(`byte "a logging message"; log;`, config.MaxLogCalls)),


Suggested change

source: fmt.Sprintf(`%s int 1`, strings.Repeat(`byte "a logging message"; log;`, config.MaxLogCalls)),

source: fmt.Sprintf(`%s int 1`, strings.Repeat(`byte "a logging message"; log;`, MaxLogCalls)),

algorandskiy · 2021-08-09T19:21:54Z

+			runMode:     runModeApplication,
+		},
+		{
+			source:      fmt.Sprintf(`%s; int 1`, strings.Repeat(`byte "a"; log;`, config.MaxLogCalls+1)),


Suggested change

source: fmt.Sprintf(`%s; int 1`, strings.Repeat(`byte "a"; log;`, config.MaxLogCalls+1)),

source: fmt.Sprintf(`%s; int 1`, strings.Repeat(`byte "a"; log;`, MaxLogCalls+1)),

jasonpaulos · 2021-08-09T20:45:01Z

 		return false
 	}

+	// Logs must be equal


You should compare the lengths of the logs before iterating over them

jasonpaulos · 2021-08-09T20:48:03Z

+	d1 = EvalDelta{
+		Logs: []LogItem{{ID: 0, Message: "val"}},
+	}
+	a.True(d1.Equal(d2))


Suggested test case: compare two EvalDeltas with logs [A] and [A, B] -- I believe this would currently pass because of the length issue I mentioned

jasonpaulos · 2021-08-09T20:50:26Z

+// not valid.
+func (ac *ApplicationCallTxnFields) AppIDByIndex(i uint64) (basics.AppIndex, error) {
+
+	// Index 0 always corresponds to the sender


nit: sender still mentioned here and in function below

jasonpaulos · 2021-08-09T20:53:38Z

+	idx, err := txn.IndexByAppID(txn.ApplicationID)
+	if err != nil {
+		return err
+	}


Just to be paranoid, could you return an error if idx != 0? It shouldn't happen, but it would be really bad if it did happen

jasonpaulos · 2021-08-09T20:57:34Z

+		return false
+	}
+	for i, e := range expected {
+		if e.ID != actual[i].ID || e.Message != actual[i].Message {


nit: you could use the Equals method you made here

jasonpaulos · 2021-08-09T20:59:34Z

+	a.Equal(32, len(*txn.Logs))
+	for i, l := range *txn.Logs {
+		a.Equal(expectedAppID, l.Id)
+		assert.Equal(t, base64.StdEncoding.EncodeToString([]byte(string(rune('B'+i)))), l.Value)


nit: is it necessary to import assert instead of using a.Equal?

jasonpaulos

partitiontest.PartitionTest may need to be added to tests to satisfy reviewdog (I don't know the purpose of that), but this looks good to me

shiqizng added 8 commits July 7, 2021 09:23

new opcode

52254a4

Merge remote-tracking branch 'upstream/master' into opcode/log

1f5f64e

adding log

dc2ee1b

Merge branch 'master' of https://github.com/algorand/go-algorand into…

a8fab5b

… opcode/log

added unit tests

3196118

more tests

7f261cc

update evalDelta test in app

1e427c1

fmt updates

47a9b74

shiqizng requested review from jannotti, jasonpaulos and jdtzmn July 13, 2021 15:22

jannotti reviewed Jul 13, 2021

View reviewed changes

Comment thread data/transactions/logic/doc.go

Comment thread data/transactions/logic/eval.go Outdated

Comment thread data/transactions/logic/eval.go Outdated

Comment thread data/transactions/logic/evalStateful_test.go Outdated

Comment thread ledger/appcow.go Outdated

tsachiherman reviewed Jul 13, 2021

View reviewed changes

Comment thread data/transactions/logic/eval.go Outdated

shiqizng added 3 commits July 13, 2021 14:08

addressing pr feedback

0806abb

update var names

366d0a8

update log call limit to 32

68ca45c

shiqizng requested a review from AyAggarwal July 13, 2021 18:30

barnjamin reviewed Jul 13, 2021

View reviewed changes

Comment thread data/transactions/logic/doc.go Outdated

doc error fix

5a595a5

jdtzmn previously approved these changes Jul 13, 2021

View reviewed changes

Comment thread data/transactions/logic/eval_test.go

Comment thread data/transactions/logic/assembler_test.go

fix msgp error

f9e61e2

shiqizng dismissed jdtzmn’s stale review via f9e61e2 July 13, 2021 20:36

run make in logic

341858b

shiqizng requested a review from jannotti July 14, 2021 14:46

jdtzmn suggested changes Jul 14, 2021

View reviewed changes

Comment thread data/basics/teal.go Outdated

move MaxLogCalls to config

fc7ce6d

winder reviewed Jul 14, 2021

View reviewed changes

jasonpaulos approved these changes Aug 3, 2021

View reviewed changes

jasonpaulos suggested changes Aug 4, 2021

View reviewed changes

jasonpaulos reviewed Aug 4, 2021

View reviewed changes

Comment thread data/basics/teal.go

Comment thread daemon/algod/api/server/v2/dryrun_test.go

algorandskiy reviewed Aug 4, 2021

View reviewed changes

addressed pr reviews

b18e435

shiqizng requested review from algorandskiy and jasonpaulos August 5, 2021 15:10

algorandskiy reviewed Aug 9, 2021

View reviewed changes

shiqizng added 6 commits August 9, 2021 13:59

changes as per review

1e8ef62

resolve merge conflicts

7c286bc

update maxlogcalls val

c88dfae

fix failing tests

4fb6e4e

remove getLogs()

eb3ace4

remove getLogs

023c440

algorandskiy reviewed Aug 9, 2021

View reviewed changes

algorandskiy previously approved these changes Aug 9, 2021

View reviewed changes

fix failing tests

bb65c70

shiqizng dismissed algorandskiy’s stale review via bb65c70 August 9, 2021 20:16

jasonpaulos suggested changes Aug 9, 2021

View reviewed changes

changes as per review

c9504e1

jasonpaulos previously approved these changes Aug 9, 2021

View reviewed changes

fix failing tests and resolve reviewdog warnings

a86db27

shiqizng dismissed jasonpaulos’s stale review via a86db27 August 10, 2021 00:34

fix failing tests

f375213

jasonpaulos approved these changes Aug 10, 2021

View reviewed changes

jannotti approved these changes Aug 11, 2021

View reviewed changes

jannotti merged commit 58bc231 into algorand:master Aug 11, 2021

This was referenced Aug 19, 2021

DO NOT MERGE --- go-algorand 2.10.0-stable #2773

Closed

go-algorand 2.10.1-beta #2800

Merged

bricerisingalgorand mentioned this pull request Aug 27, 2021

go-algorand 2.10.1-stable #2813

Merged

	const MaxLogCalls = config.MaxLogCalls
	const MaxLogCalls = 32

	source: fmt.Sprintf(`%s int 1`, strings.Repeat(`byte "a logging message"; log;`, config.MaxLogCalls)),
	source: fmt.Sprintf(`%s int 1`, strings.Repeat(`byte "a logging message"; log;`, MaxLogCalls)),

	source: fmt.Sprintf(`%s; int 1`, strings.Repeat(`byte "a"; log;`, config.MaxLogCalls+1)),
	source: fmt.Sprintf(`%s; int 1`, strings.Repeat(`byte "a"; log;`, MaxLogCalls+1)),

Conversation

shiqizng commented Jul 13, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jannotti left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

runvnc commented Jul 13, 2021

Uh oh!

jannotti commented Jul 13, 2021

Uh oh!

Uh oh!

Uh oh!

Uh oh!

codecov-commenter commented Jul 13, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

jdtzmn left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jasonpaulos left a comment

Choose a reason for hiding this comment

Uh oh!

jasonpaulos left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

algorandskiy left a comment

Choose a reason for hiding this comment

Uh oh!

shiqizng commented Jul 13, 2021 •

edited

Loading

codecov-commenter commented Jul 13, 2021 •

edited

Loading

jasonpaulos left a comment •

edited

Loading