T4 testnet stuck at 1860892

[roman-khimov]

There is some state diff there with 0.98.5:

июн 24 13:59:49 suigintou docker-compose[672706]: neogo-n3-testnet-rpc    | 2022-06-24T13:59:49.326Z        WARN        blockQueue: failed adding block into the blockchain        {"error": "onPersist failed: VM has failed: at instruction 0 (SYSCALL): insufficient funds", "blockHeight": 1860892, "nextIndex": 1860893}

It needs to be investigated even though we have no plans for 0.98.X line updates.

[roman-khimov]

The transaction there is https://n3t4.neotube.io/transaction/0x05ed667568a38a4d3517175ecfcef3356e0ef9647fa7ddfc15243cb3af2af1f6, but the problem is likely to happen earlier. I've seen a report of a problem with this block for C# node also which is rather strange (as the network seems to be moving forward anyway).

[AnnaShaleva]

Current research status:
The statediff is at block #975644:

$ go run scripts/compare-states/compare-states.go --ignore-height http://seed1t4.neo.org:20332 http://rpc1.testnet.n3.nspcc.ru:20332
at 0: 4991e8fd99f7decaab9b46dc00ac7484a65b7cd859273ac29cfff6d63e9fd238 vs 4991e8fd99f7decaab9b46dc00ac7484a65b7cd859273ac29cfff6d63e9fd238
at 1860892: 0fc0ce9f74e84fa989822541b2c0a5cb8d36180be20457bb1b08c51dc894e2e9 vs 2b0158a777be10a2e7a3c5deb8df414b42d00b4ab9847428901d03d6d49ac73b
at 930446: e0bb5a259bd64d54b3083ab2c5909712ca969b4ce3b1283ef3e356374e974563 vs e0bb5a259bd64d54b3083ab2c5909712ca969b4ce3b1283ef3e356374e974563
at 1395669: 5851327545c1cd922bd778461777483d48e9c83ba8d33ed058b6b78a1ba8ecd7 vs 03406fae13cd99c2171bf3349ac2955d3d9e848e6c3c79ea3311517a492d63ca
at 1163057: 6588f07f0c1e0683e41f03414059e237985a451bf4f6aa3333238938572da692 vs 460ff8b0c449c4e9badd6e81185e3e4a80fbb65d46badda5ace47cff68a61559
at 1046751: f97c370d80b35f10f879375fdc958ea20e7ec540331216997617b1f084b40d9c vs bd9eb5008b706e3f6d49b53521d8ba9855348f89ce27660db2d3da0099b13787
at 988598: 242850cbd0e90af8550d71f1984c593008e8deb6299cb6278091fd05f7e3b885 vs 9b0eb042d1a05c9e38ee54468c19e9cf7f7a63793580969f585180eaf1b2d57b
at 959522: 2359101b392c38a028eae504eb628322cd21824dd0d303f1d721dba806d1b800 vs 2359101b392c38a028eae504eb628322cd21824dd0d303f1d721dba806d1b800
at 974060: 3b8a952575aec06cf8664fed467d84f81d2f8adfe841435f239b52dc6a92d953 vs 3b8a952575aec06cf8664fed467d84f81d2f8adfe841435f239b52dc6a92d953
at 981329: 20e7161d96be1e717528a74e2154647df18df03b0ed606cefe447de0573a912a vs ef07d328eed1ecc4cad0e811ad11173c92f3d3e0f10809bf1ef557c3adfd43fd
at 977694: 5c7d49b63b5d8e3edfa895056697714ae8fd291e09288c1b098660a91a46986b vs 68a4a11c1730056b574f671e7d1b00d41f1f7134a2a90a7fa0d8a82b88e8a47d
at 975877: f28be6a9a8fb91be7a7120ad754178b6848527448375ce106bba9836bc9f9e00 vs 989b5d87357289a69b0215b3d4651ab66a3ae324edb93be8173ad36392ae16ba
at 974968: 6bc9816d87274bca2a492198f6b6a598c474d8acf1ed2630aff9f32dca790fba vs 6bc9816d87274bca2a492198f6b6a598c474d8acf1ed2630aff9f32dca790fba
at 975422: 5af3350b734e28a0712828588c72857844f723c68ad5d9842d6e572a7098aa88 vs 5af3350b734e28a0712828588c72857844f723c68ad5d9842d6e572a7098aa88
at 975649: ce3d1e9377421d3e59fdee47aec0e6c428a38e4b8795ac9194869dd93f431cda vs 50b27c85edde24bbc51e0fb1ddee60f727b9b4ce27801299e5e6d36f99eceea6
at 975535: 353270dcddb830360aec3aaf69a5e420e5bc6bbc441b86e6e64fc597408491f4 vs 353270dcddb830360aec3aaf69a5e420e5bc6bbc441b86e6e64fc597408491f4
at 975592: 77d78a57a3e382a2d427c96a8228101b3581086a82c62240297bfcda232a68ca vs 77d78a57a3e382a2d427c96a8228101b3581086a82c62240297bfcda232a68ca
at 975620: dd27e743fdd90c75e8753ec71f161c6a3d19a8795fe3b047e2b1ea09c38efd84 vs dd27e743fdd90c75e8753ec71f161c6a3d19a8795fe3b047e2b1ea09c38efd84
at 975634: 51a3d4717581d7697e51103116f4c8d9cd31bd48ff3fa885686ec73326d12e7e vs 51a3d4717581d7697e51103116f4c8d9cd31bd48ff3fa885686ec73326d12e7e
at 975641: a6aa2fc5c2d09299c8a1f8a83f764f5f5f252c8a07c6f0d60e51f634181a4b91 vs a6aa2fc5c2d09299c8a1f8a83f764f5f5f252c8a07c6f0d60e51f634181a4b91
at 975645: 3894cd09a805840bb86a7e917cb38aa126b51d79d35548dc09a5a270fd164f11 vs 525df6edcc9b7bc013d74addbcc6593958d7f9c248072dec723de684d554d962
at 975643: dbd493a39b675d5d754f80093ded218f10132bc6ac4fd91163b382f2227cb53d vs dbd493a39b675d5d754f80093ded218f10132bc6ac4fd91163b382f2227cb53d
at 975644: 15ff7e2efe980bf370731e236860eb3ec5c4c42d738d200fb29a83f7427e8e58 vs 7ce0646cd4a9f7a85176f86f22b913d94e148f8b91d43698def9cb81619933da
state differs at 975644, block 968498b605351e01e266f8cabc4dbdebff0a4ffaec2862fa3088f30b424536bb
transaction a53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424:
--- http://seed1t4.neo.org:20332
+++ http://rpc1.testnet.n3.nspcc.ru:20332
@@ -1,2 +1,2 @@
-(*result.ApplicationLog)(0xc000410300)({
+(*result.ApplicationLog)(0xc000528300)({
  Container: (util.Uint256) (len=32 cap=32) 24a49d8c2f810aee47fd2160c457cb4c6c07053a0a5c02a6380e2b1d382539a5,
@@ -6,9 +6,7 @@
    Trigger: (trigger.Type) Application,
-   VMState: (vm.State) HALT,
-   GasConsumed: (int64) 6440674,
-   Stack: ([]stackitem.Item) (len=2 cap=2) {
-    (stackitem.Null) Null,
-    (stackitem.Null) Null
+   VMState: (vm.State) FAULT,
+   GasConsumed: (int64) 3410217,
+   Stack: ([]stackitem.Item) {
    },
-   Events: ([]state.NotificationEvent) (len=2 cap=4) {
+   Events: ([]state.NotificationEvent) (len=1 cap=4) {
     (state.NotificationEvent) {
@@ -16,11 +14,6 @@
      Name: (string) (len=8) "Transfer",
-     Item: (*stackitem.Array)(0xc0003ec720)(Array)
-    },
-    (state.NotificationEvent) {
-     ScriptHash: (util.Uint160) (len=20 cap=20) a39b664c3fadde872b1e3b3b4518aadf7d54b69c,
-     Name: (string) (len=8) "Transfer",
-     Item: (*stackitem.Array)(0xc0003ec960)(Array)
+     Item: (*stackitem.Array)(0xc0002429f0)(Array)
     }
    },
-   FaultException: (string) ""
+   FaultException: (string) (len=60) "at instruction 22 (SYSCALL): expected byte size of 20 got 42"
   }

different state found
exit status 1

The problem transaction is FAULTed on Go node and HALTed on C# node.
Go node's application log:

$ curl -d '{ "jsonrpc": "2.0", "id": 1, "method": "getapplicationlog", "params": ["a53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424"] }' http://rpc1.testnet.n3.nspcc.ru:20332 | json_pp
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   727  100   587  100   140   1924    459 --:--:-- --:--:-- --:--:--  2383
{
   "result" : {
      "txid" : "0xa53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424",
      "executions" : [
         {
            "vmstate" : "FAULT",
            "trigger" : "Application",
            "gasconsumed" : "3410217",
            "exception" : "at instruction 22 (SYSCALL): expected byte size of 20 got 42",
            "notifications" : [
               {
                  "state" : {
                     "type" : "Array",
                     "value" : [
                        {
                           "type" : "Any"
                        },
                        {
                           "value" : "MHgyMjk2YmQzMjMwMDRiNDM5ZjQ2ZDE1NTdiN2I1OGE4ZjZjZmUzNmFm",
                           "type" : "ByteString"
                        },
                        {
                           "type" : "Integer",
                           "value" : "1"
                        },
                        {
                           "type" : "ByteString",
                           "value" : "MQ=="
                        }
                     ]
                  },
                  "contract" : "0x9cb6547ddfaa18453b3b1e2b87dead3f4c669ba3",
                  "eventname" : "Transfer"
               }
            ],
            "stack" : []
         }
      ]
   },
   "jsonrpc" : "2.0",
   "id" : 1
}

C# node's application log:

$ curl -d '{ "jsonrpc": "2.0", "id": 1, "method": "getapplicationlog", "params": ["a53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424"] }' http://seed1t4.neo.org:20332 | json_pp
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   984    0   844  100   140   1562    259 --:--:-- --:--:-- --:--:--  1818
{
   "result" : {
      "txid" : "0xa53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424",
      "executions" : [
         {
            "stack" : [
               {
                  "type" : "Any"
               },
               {
                  "type" : "Any"
               }
            ],
            "notifications" : [
               {
                  "contract" : "0x9cb6547ddfaa18453b3b1e2b87dead3f4c669ba3",
                  "eventname" : "Transfer",
                  "state" : {
                     "type" : "Array",
                     "value" : [
                        {
                           "type" : "Any"
                        },
                        {
                           "type" : "ByteString",
                           "value" : "MHgyMjk2YmQzMjMwMDRiNDM5ZjQ2ZDE1NTdiN2I1OGE4ZjZjZmUzNmFm"
                        },
                        {
                           "type" : "Integer",
                           "value" : "1"
                        },
                        {
                           "type" : "ByteString",
                           "value" : "MQ=="
                        }
                     ]
                  }
               },
               {
                  "state" : {
                     "value" : [
                        {
                           "type" : "Any"
                        },
                        {
                           "value" : "MHgyMjk2YmQzMjMwMDRiNDM5ZjQ2ZDE1NTdiN2I1OGE4ZjZjZmUzNmFm",
                           "type" : "ByteString"
                        },
                        {
                           "type" : "Integer",
                           "value" : "1"
                        },
                        {
                           "value" : "MTE=",
                           "type" : "ByteString"
                        }
                     ],
                     "type" : "Array"
                  },
                  "eventname" : "Transfer",
                  "contract" : "0x9cb6547ddfaa18453b3b1e2b87dead3f4c669ba3"
               }
            ],
            "exception" : null,
            "gasconsumed" : "6440674",
            "vmstate" : "HALT",
            "trigger" : "Application"
         }
      ]
   },
   "jsonrpc" : "2.0",
   "id" : 1
}

The transaction itself:

$ curl -d '{ "jsonrpc": "2.0", "id": 1, "method": "getrawtransaction", "params": ["a53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424", 1] }' http://rpc1.testnet.n3.nspcc.ru:20332 | json_pp
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1129  100   986  100   143   3806    552 --:--:-- --:--:-- --:--:--  4359
{
   "result" : {
      "blocktime" : 1641981655377,
      "version" : 0,
      "netfee" : "134052",
      "blockhash" : "0x968498b605351e01e266f8cabc4dbdebff0a4ffaec2862fa3088f30b424536bb",
      "attributes" : [],
      "sender" : "NbtRKN9wPV7WMAQFhVGsecDfNcHZcWkKoY",
      "script" : "DAE1DAE0DAEzDAEyDAExDCoweDIyOTZiZDMyMzAwNGI0MzlmNDZkMTU1N2I3YjU4YThmNmNmZTM2YWYWwB8MBmNyZWF0ZQwUo5tmTD+t3ocrHjs7RRiq331UtpxBYn1bUgwCNTUMAjQ0DAIzMwwCMjIMAjExDCoweDIyOTZiZDMyMzAwNGI0MzlmNDZkMTU1N2I3YjU4YThmNmNmZTM2YWYWwB8MBmNyZWF0ZQwUo5tmTD+t3ocrHjs7RRiq331UtpxBYn1bUg==",
      "witnesses" : [
         {
            "invocation" : "DEAZ13idr9M2cxTwG1XdGjsc2IvngveZgjhoMTRtpZ62IeZGlJntAJ4+dJITcyqqOkUurJtMFENcqyFSt/40/7aU",
            "verification" : "DCEClkwZkaNYLR3sahOgSLEonyw71qGQxYEIpGwH95rir8xBVuezJw=="
         }
      ],
      "size" : 357,
      "sysfee" : "6440674",
      "validuntilblock" : 981402,
      "signers" : [
         {
            "account" : "0x2296bd323004b439f46d1557b7b58a8f6cfe36af",
            "scopes" : "Global"
         }
      ],
      "confirmations" : 885249,
      "hash" : "0xa53925381d2b0e38a6025c0a3a05076c4ccb57c46021fd47ee0a812f8c9da424",
      "nonce" : 969344684,
      "vmstate" : "FAULT"
   },
   "id" : 1,
   "jsonrpc" : "2.0"
}

The transaction contains two subsequent contract calls:

NEO-GO-VM > loadbase64 DAE1DAE0DAEzDAEyDAExDCoweDIyOTZiZDMyMzAwNGI0MzlmNDZkMTU1N2I3YjU4YThmNmNmZTM2YWYWwB8MBmNyZWF0ZQwUo5tmTD+t3ocrHjs7RRiq331UtpxBYn1bUgwCNTUMAjQ0DAIzMwwCMjIMAjExDCoweDIyOTZiZDMyMzAwNGI0MzlmNDZkMTU1N2I3YjU4YThmNmNmZTM2YWYWwB8MBmNyZWF0ZQwUo5tmTD+t3ocrHjs7RRiq331UtpxBYn1bUg==
READY: loaded 199 instructions
NEO-GO-VM 0 > ops
INDEX    OPCODE       PARAMETER
0        PUSHDATA1    35 ("5")    <<
3        PUSHDATA1    34 ("4")
6        PUSHDATA1    33 ("3")
9        PUSHDATA1    32 ("2")
12       PUSHDATA1    31 ("1")
15       PUSHDATA1    307832323936626433323330303462343339663436643135353762376235386138663663666533366166 ("0x2296bd323004b439f46d1557b7b58a8f6cfe36af")
59       PUSH6        
60       PACK         
61       PUSH15       
62       PUSHDATA1    637265617465 ("create")
70       PUSHDATA1    a39b664c3fadde872b1e3b3b4518aadf7d54b69c
92       SYSCALL      System.Contract.Call (627d5b52)
97       PUSHDATA1    3535 ("55")
101      PUSHDATA1    3434 ("44")
105      PUSHDATA1    3333 ("33")
109      PUSHDATA1    3232 ("22")
113      PUSHDATA1    3131 ("11")
117      PUSHDATA1    307832323936626433323330303462343339663436643135353762376235386138663663666533366166 ("0x2296bd323004b439f46d1557b7b58a8f6cfe36af")
161      PUSH6        
162      PACK         
163      PUSH15       
164      PUSHDATA1    637265617465 ("create")
172      PUSHDATA1    a39b664c3fadde872b1e3b3b4518aadf7d54b69c
194      SYSCALL      System.Contract.Call (627d5b52)

The part of the contract code where Go node fails contains call to native Management's getContract method. Go node FAULTs the execution because the argument of getContract can't be converted to Hash160 type right here:

neo-go/pkg/core/native/management.go

Line 162 in 2f55070

ctr, err := m.GetContract(ic.DAO, hash)

hashBytes argument is a stackitem with ByteString type and []byte{48, 120, 50, 50, 57, 54, 98, 100, 51, 50, 51, 48, 48, 52, 98, 52, 51, 57, 102, 52, 54, 100, 49, 53, 53, 55, 98, 55, 98, 53, 56, 97, 56, 102, 54, 99, 102, 101, 51, 54, 97, 102} value (which is Utf-8 bytes of string 0x2296bd323004b439f46d1557b7b58a8f6cfe36af). It's not a 20-lenght Hash160 bytes, thus Go node can't decode this ByteString into Hash160.
Here's the part of contract code where panic occurs:

999      INITSLOT     1 local, 4 arg
1002     NEWARRAY0                         // The method is started from `Transfer` notification arguments preparation.
1003     DUP          
1004     LDARG0       
1005     APPEND       
1006     DUP          
1007     LDARG1                            // Here LDARG1 loads `ByteString` stackitem with "MHgyMjk2YmQzMjMwMDRiNDM5ZjQ2ZDE1NTdiN2I1OGE4ZjZjZmUzNmFm" value (from `Notifications` field of `getapplicationlog` RPC response of both Go and C# nodes), it's the base64-encoded representation of string `0x2296bd323004b439f46d1557b7b58a8f6cfe36af`.
1008     APPEND       
1009     DUP          
1010     PUSH1        
1011     APPEND       
1012     DUP          
1013     LDARG2       
1014     APPEND       
1015     PUSHDATA1    5472616e73666572 ("Transfer")
1025     SYSCALL      System.Runtime.Notify (95016f61) // Here the first `Transfer` notification is emitted. It can be seen in both Go and C# application logs.
1030     LDARG1                            // Here the same `ByteString` is loaded cnd checked against NULL.
1031     STLOC0       
1032     LDLOC0       
1033     PUSHNULL     
1034     EQUAL        
1035     NOT          
1036     JMPIF        1043 (7/07)          // Loaded `ByteString` is not null, so jump to 1043.

1038     PUSH0                             // Skip.
1039     CONVERT      Boolean (20)         // Skip.
1041     JMP          1052 (11/0b)         // Skip.  

1043     LDARG1                            // Load the same non-null ByteString.
1044     CALLT        0200 ("\x02\x00")    // Call contract token with index 2, which is `getContract` method of native Management contract. Panic inside this method.

This ByteString is loaded into VM right from the transaction script (instruction N15):

15       PUSHDATA1    307832323936626433323330303462343339663436643135353762376235386138663663666533366166 ("0x2296bd323004b439f46d1557b7b58a8f6cfe36af")

So its VM representation is correct. The most interesting thing is that C# node has the same ByteString emitted by the contract instruction N1025:

1025     SYSCALL      System.Runtime.Notify (95016f61) // Here the first `Transfer` notification is emitted. It can be seen in both Go and C# application logs.

First notification from the application log of both C# and Go nodes is the same, but somehow C# node converts this 42-bytes-lengh ByteString into Hash160 and uses it inside Management's getContract. I thought that the reason may be somewhere around this line and this line where conversion from stackitem to native method argument occurs. I tested this C# code and the test doesn't allow such conversion as intended.

So keep researching.

[roman-khimov]

Hmm, that was #2337 and neo-project/neo#2654, we're supposed to have something different now.

[AnnaShaleva]

Turns out that current t4 seeds (seed1t4.neo.org, seed2t4.neo.org, ...) has v3.1.0.1 of neo-cli installed (neo-project/neo-node@6068447), but I wasn't able to find 3.1.0.1 release of core Neo repo. Seems that current t4 C# nodes don't have this logic. To check this I made the following changes based on 0.98.5:

diff --git a/pkg/core/native/management.go b/pkg/core/native/management.go
index a4b11a6f..1ad61d94 100644
--- a/pkg/core/native/management.go
+++ b/pkg/core/native/management.go
@@ -132,7 +132,12 @@ func (m *Management) getContract(ic *interop.Context, args []stackitem.Item) sta
        }
        hash, err := util.Uint160DecodeBytesBE(hashBytes)
        if err != nil {
-               panic(err)
+               if len(hashBytes) >= util.Uint160Size {
+                       hash, err = util.Uint160DecodeBytesBE(hashBytes[:util.Uint160Size])
+               }
+               if err != nil {
+                       panic(err)
+               }
        }
        ctr, err := m.GetContract(ic.DAO, hash)
        if err != nil {

With this change states are match up to the current t4 height:

anna@kiwi:~/Documents/GitProjects/neo-go$ go run scripts/compare-states/compare-states.go --ignore-height http://seed1t4.neo.org:20332 http://localhost:20332
at 0: 4991e8fd99f7decaab9b46dc00ac7484a65b7cd859273ac29cfff6d63e9fd238 vs 4991e8fd99f7decaab9b46dc00ac7484a65b7cd859273ac29cfff6d63e9fd238
at 1893029: 7d998c1989f0903cfd9ce08ca22c609ca5cf2c57750e28edbbbab4959cc90e96 vs 7d998c1989f0903cfd9ce08ca22c609ca5cf2c57750e28edbbbab4959cc90e96

So this issue is a consequence of the fact that t4 C# nodes do not include mentioned Uint160 fix.

[AnnaShaleva]

Not sure, do we need an issue in C# repo?

[roman-khimov]

T4 won't be updated from the C# side, so the only question that is relevant now is do we care about T4 enough to release 0.98.6? It's obsolete now, so I'd rather just move on to T5. @realloc, @alexvanin, @fyrchik?

Still, it's good to know that this issue doesn't affect 0.99.0 and T5/mainnet.

[alexvanin]

I think we can announce that new NeoFS nodes and containers won't be accepted in the T4 Testnet until it will go away completely (we were targeting the august). FS.CDN community test can be launched in T5 Testnet.