[855 12-16 15:09:31.57 UTC] [%{longpkg}] %{callpath} -> DEBU Starting new Broadcast handler [856 12-16 15:09:31.57 UTC] [%{longpkg}] %{callpath} -> DEBU Starting new broadcast loop for 172.16.12.137:48138 [857 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Broadcast is processing normal message from 172.16.12.137:48138 with txid '644502badff9767624fd083af8a3d40bd4c10351afdff44ae0f771f6cf587d98' of type ENDORSER_TRANSACTION [858 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *policies.implicitMetaPolicy Policy /Channel/Writers == [859 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU This is an implicit meta policy, it will trigger other policy evaluations, whose failures may be benign [85a 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *policies.implicitMetaPolicy Policy /Channel/Application/Writers == [85b 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU This is an implicit meta policy, it will trigger other policy evaluations, whose failures may be benign [85c 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *cauthdsl.policy Policy /Channel/Application/OrgzgMSP/Writers == [85d 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 gate 1544972971591225817 evaluation starts [85e 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 signed by 0 principal evaluation starts (used [false]) [85f 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 processing identity 0 with bytes of 0a084f72677a674d535012ef082d2d2d2d2d424547494e2043455254494649434154452d2d2d2d2d0a4d4949444744434341722b6741774942416749554a52355638517a6e72797048544a436d41576e426e57745847765577436759494b6f5a497a6a3045417749770a6144454c4d416b474131554542684d4356564d78467a415642674e5642416754446b3576636e526f49454e68636d3973615735684d525177456759445651514b0a457774496558426c636d786c5a47646c636a45504d4130474131554543784d47526d4669636d6c6a4d526b7746775944565151444578426d59574a7961574d740a5932457463325679646d56794d423458445445344d5449784e6a45304e4451774d466f58445445354d5449784e6a45304e446b774d466f77675a7378437a414a0a42674e5642415954416c56544d52637746515944565151494577354f62334a306143424459584a7662476c75595445554d4249474131554543684d4c53486c770a5a584a735a57526e5a5849784f6a414e42674e5642417354426d4e73615756756444414b42674e564241735441324e766254415342674e5642417354433246790a6447567965574e6f59576c754d416b474131554543784d43656d63784954416642674e5642414d4d4745466b62576c755148706e4c6d46796447567965574e6f0a59576c754c6d4e766254425a4d424d4742797147534d34394167454743437147534d3439417745484130494142504170484a3744626a575467627744354339620a69465739495450355a304153387446774c6b4f6653616e41544f7455663368724b6741543156345a565574684d78766f69304d4a51582b614c51534e77724f2f0a6e72696a676745524d4949424454414f42674e56485138424166384542414d434234417744415944565230544151482f424149774144416442674e56485134450a466751556339357354615841456855666a42644758586b347863786e35384977487759445652306a42426777466f41556d384d565568514a676e6b58596649550a58784d7a7a57746235573477485159445652305242425977464949535932457559584a305a584a355932686861573475593239744d49474e42676771417751460a42676349415153426748736959585230636e4d694f6e73696147597551575a6d6157787059585270623234694f694a6a6232307559584a305a584a35593268680a61573475656d63694c434a6f5a693546626e4a76624778745a573530535551694f694a425a473170626b42365a793568636e526c636e6c6a614746706269356a0a623230694c434a6f5a6935556558426c496a6f69593278705a57353049697769636d39735a534936496d466b62576c75496e31394d416f4743437147534d34390a42414d43413063414d45514349433357306c487168394d314332726c4a4544503933436147693642677557484674524376462b776a31724341694171747058640a4567755063785046592b6a557a5133495a3245477a72487072485538386e6b774f7935454f773d3d0a2d2d2d2d2d454e442043455254494649434154452d2d2d2d2d0a [860 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 principal matched by identity 0 [861 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU Verify: digest = 00000000 88 65 0b 14 56 ae b3 7a 3e 1b 96 5b 93 e0 e0 fe |.e..V..z>..[....| 00000010 1e 3e 8b 63 ca 12 2b 35 e3 56 14 15 11 64 b3 0b |.>.c..+5.V...d..| [862 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU Verify: sig = 00000000 30 44 02 20 68 9f 15 86 82 05 4d e0 49 5d 49 cc |0D. h.....M.I]I.| 00000010 75 88 67 ee 55 7f a1 7b 8e 5b 5b c1 68 bd bd 34 |u.g.U..{.[[.h..4| 00000020 71 65 54 03 02 20 05 ef c8 50 63 ac 9e d2 d3 e9 |qeT.. ...Pc.....| 00000030 5b ea 0f fe 18 32 6a 5b 72 cf 74 d5 e3 cb f7 44 |[....2j[r.t....D| 00000040 8e 37 aa d4 4d d5 |.7..M.| [863 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 principal evaluation succeeds for identity 0 [864 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc4201661c0 gate 1544972971591225817 evaluation succeeds [865 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Application/OrgzgMSP/Writers [866 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *cauthdsl.policy Policy /Channel/Application/OrgzgMSP/Writers [867 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Application/Writers [868 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *policies.implicitMetaPolicy Policy /Channel/Application/Writers [869 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Writers [86a 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *policies.implicitMetaPolicy Policy /Channel/Writers [86b 12-16 15:09:31.59 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Enqueueing envelope... [86c 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Envelope enqueued successfully [86d 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Broadcast has successfully enqueued message of type ENDORSER_TRANSACTION from 172.16.12.137:48138 [86e 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Successfully unmarshalled consumed message, offset is 15. Inspecting type... [86f 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Processing regular Kafka message of type NORMAL [870 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> WARN [channel: pubchannel] This orderer is running in compatibility mode [871 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *policies.implicitMetaPolicy Policy /Channel/Writers == [872 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU This is an implicit meta policy, it will trigger other policy evaluations, whose failures may be benign [873 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *policies.implicitMetaPolicy Policy /Channel/Application/Writers == [874 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU This is an implicit meta policy, it will trigger other policy evaluations, whose failures may be benign [875 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Evaluating *cauthdsl.policy Policy /Channel/Application/OrgzgMSP/Writers == [876 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 gate 1544972971608527916 evaluation starts [877 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 signed by 0 principal evaluation starts (used [false]) [878 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 processing identity 0 with bytes of 0a084f72677a674d535012ef082d2d2d2d2d424547494e2043455254494649434154452d2d2d2d2d0a4d4949444744434341722b6741774942416749554a52355638517a6e72797048544a436d41576e426e57745847765577436759494b6f5a497a6a3045417749770a6144454c4d416b474131554542684d4356564d78467a415642674e5642416754446b3576636e526f49454e68636d3973615735684d525177456759445651514b0a457774496558426c636d786c5a47646c636a45504d4130474131554543784d47526d4669636d6c6a4d526b7746775944565151444578426d59574a7961574d740a5932457463325679646d56794d423458445445344d5449784e6a45304e4451774d466f58445445354d5449784e6a45304e446b774d466f77675a7378437a414a0a42674e5642415954416c56544d52637746515944565151494577354f62334a306143424459584a7662476c75595445554d4249474131554543684d4c53486c770a5a584a735a57526e5a5849784f6a414e42674e5642417354426d4e73615756756444414b42674e564241735441324e766254415342674e5642417354433246790a6447567965574e6f59576c754d416b474131554543784d43656d63784954416642674e5642414d4d4745466b62576c755148706e4c6d46796447567965574e6f0a59576c754c6d4e766254425a4d424d4742797147534d34394167454743437147534d3439417745484130494142504170484a3744626a575467627744354339620a69465739495450355a304153387446774c6b4f6653616e41544f7455663368724b6741543156345a565574684d78766f69304d4a51582b614c51534e77724f2f0a6e72696a676745524d4949424454414f42674e56485138424166384542414d434234417744415944565230544151482f424149774144416442674e56485134450a466751556339357354615841456855666a42644758586b347863786e35384977487759445652306a42426777466f41556d384d565568514a676e6b58596649550a58784d7a7a57746235573477485159445652305242425977464949535932457559584a305a584a355932686861573475593239744d49474e42676771417751460a42676349415153426748736959585230636e4d694f6e73696147597551575a6d6157787059585270623234694f694a6a6232307559584a305a584a35593268680a61573475656d63694c434a6f5a693546626e4a76624778745a573530535551694f694a425a473170626b42365a793568636e526c636e6c6a614746706269356a0a623230694c434a6f5a6935556558426c496a6f69593278705a57353049697769636d39735a534936496d466b62576c75496e31394d416f4743437147534d34390a42414d43413063414d45514349433357306c487168394d314332726c4a4544503933436147693642677557484674524376462b776a31724341694171747058640a4567755063785046592b6a557a5133495a3245477a72487072485538386e6b774f7935454f773d3d0a2d2d2d2d2d454e442043455254494649434154452d2d2d2d2d0a [879 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 principal matched by identity 0 [87a 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Verify: digest = 00000000 88 65 0b 14 56 ae b3 7a 3e 1b 96 5b 93 e0 e0 fe |.e..V..z>..[....| 00000010 1e 3e 8b 63 ca 12 2b 35 e3 56 14 15 11 64 b3 0b |.>.c..+5.V...d..| [87b 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Verify: sig = 00000000 30 44 02 20 68 9f 15 86 82 05 4d e0 49 5d 49 cc |0D. h.....M.I]I.| 00000010 75 88 67 ee 55 7f a1 7b 8e 5b 5b c1 68 bd bd 34 |u.g.U..{.[[.h..4| 00000020 71 65 54 03 02 20 05 ef c8 50 63 ac 9e d2 d3 e9 |qeT.. ...Pc.....| 00000030 5b ea 0f fe 18 32 6a 5b 72 cf 74 d5 e3 cb f7 44 |[....2j[r.t....D| 00000040 8e 37 aa d4 4d d5 |.7..M.| [87c 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 principal evaluation succeeds for identity 0 [87d 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU 0xc42000e050 gate 1544972971608527916 evaluation succeeds [87e 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Application/OrgzgMSP/Writers [87f 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *cauthdsl.policy Policy /Channel/Application/OrgzgMSP/Writers [880 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Application/Writers [881 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *policies.implicitMetaPolicy Policy /Channel/Application/Writers [882 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Signature set satisfies policy /Channel/Writers [883 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU == Done Evaluating *policies.implicitMetaPolicy Policy /Channel/Writers [884 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU Enqueuing message into batch [885 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Ordering results: items in batch = 0, pending = true [886 12-16 15:09:31.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Just began 2s batch timer [887 12-16 15:09:31.61 UTC] [%{longpkg}] %{callpath} -> DEBU transport: http2Server.HandleStreams failed to read frame: read tcp 172.16.12.137:7050->172.16.12.137:48138: read: connection reset by peer [888 12-16 15:09:31.61 UTC] [%{longpkg}] %{callpath} -> WARN Error reading from 172.16.12.137:48138: rpc error: code = Canceled desc = context canceled [88a 12-16 15:09:31.61 UTC] [%{longpkg}] %{callpath} -> DEBU Closing Broadcast stream [889 12-16 15:09:31.61 UTC] [%{longpkg}] %{callpath} -> DEBU transport: loopyWriter.run returning. connection error: desc = "transport is closing" [88b 12-16 15:09:33.60 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Time-to-cut block 4 timer expired [88c 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Successfully unmarshalled consumed message, offset is 16. Inspecting type... [88d 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] It's a time-to-cut message for block 4 [88e 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Nil'd the timer [88f 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Proper time-to-cut received, just cut block 4 [890 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Successfully unmarshalled consumed message, offset is 17. Inspecting type... [891 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] It's a time-to-cut message for block 4 [892 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Ignoring stale time-to-cut-message for block 4 [893 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Successfully unmarshalled consumed message, offset is 18. Inspecting type... [894 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] It's a time-to-cut message for block 4 [895 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Ignoring stale time-to-cut-message for block 4 [896 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Successfully unmarshalled consumed message, offset is 19. Inspecting type... [897 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] It's a time-to-cut message for block 4 [898 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] Ignoring stale time-to-cut-message for block 4 [899 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Obtaining default signing identity [89a 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Obtaining default signing identity [89b 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Sign: plaintext: 0AF2080A0A4F7264657265724D535012...4043C55063709492FA7B0B2317A7456F [89c 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Sign: digest: 70EC29DD7309C68E87B6EC397C82E845BA61155250B3D78D6FE205DBFA8A3C3E [89d 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Obtaining default signing identity [89e 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU [channel: pubchannel] About to write block, setting its LAST_CONFIG to 1 [89f 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Obtaining default signing identity [8a0 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Sign: plaintext: 08010AF2080A0A4F7264657265724D53...4043C55063709492FA7B0B2317A7456F [8a1 12-16 15:09:33.62 UTC] [%{longpkg}] %{callpath} -> DEBU Sign: digest: 7CD1967CD7A3EA9085F72501F9E73DDAC424E8E4D3CDD2DB9B51831D9F5DFD48 [8a2 12-16 15:09:33.64 UTC] [%{longpkg}] %{callpath} -> DEBU Indexing block [blockNum=4, blockHash=[]byte{0x99, 0x2b, 0x0, 0xcc, 0x27, 0x42, 0x39, 0xf1, 0xc8, 0xd4, 0x2f, 0x11, 0xa9, 0xae, 0xa7, 0xd, 0x62, 0x55, 0xd0, 0x15, 0x2e, 0x5b, 0xb7, 0x5d, 0x1c, 0x16, 0x2a, 0xb1, 0xfe, 0xda, 0xb0, 0x6e} txOffsets= txId=644502badff9767624fd083af8a3d40bd4c10351afdff44ae0f771f6cf587d98 locPointer=offset=70, bytesLength=3905 ] [8a3 12-16 15:09:33.65 UTC] [%{longpkg}] %{callpath} -> DEBU Broadcasting about update checkpointInfo: latestFileChunkSuffixNum=[0], latestFileChunksize=[41384], isChainEmpty=[false], lastBlockNumber=[4]