search

ethereum / go-ethereum

Go implementation of the Ethereum protocol
https://geth.ethereum.org
GNU Lesser General Public License v3.0
47.62k stars 20.16k forks source link

Startup aborted due to RPC service parsing errors #20642

Closed rfikki closed 4 years ago

rfikki commented 4 years ago

System information

Geth/v1.9.11-unstable-34bb132b-20200209/windows-amd64/go1.13.6

Expected behaviour

No crash/error

Actual behaviour

INFO [02-09|20:30:30.864] IPC endpoint opened                      url=\\\\.\\pipe\\geth.ipc
INFO [02-09|20:30:30.864] IPC endpoint closed                      url=\\\\.\\pipe\\geth.ipc
DEBUG[02-09|20:30:30.864] RPC server shutting down 
DEBUG[02-09|20:30:30.864] RPC server shutting down 
INFO [02-09|20:30:30.864] Blockchain manager stopped 
DEBUG[02-09|20:30:30.864] Reset ancient limit to zero 
INFO [02-09|20:30:30.864] Transaction pool stopped 
INFO [02-09|20:30:30.912] Light ethereum stopped 
INFO [02-09|20:30:30.912] whisper stopped 
DEBUG[02-09|20:30:30.912] Read error                               err="accept tcp [::]:30303: use of closed network connection"
TRACE[02-09|20:30:30.912] P2P networking is spinning down 
DEBUG[02-09|20:30:30.913] Read error: read udp [::]:30303: use of closed network connection 
TRACE[02-09|20:30:30.913] <-net.closeReq 
TRACE[02-09|20:30:30.913] loop stopped 
DEBUG[02-09|20:30:30.913] shutting down 
TRACE[02-09|20:30:30.972] Setting up connection failed             addr=3.11.147.67:30303 err="server stopped"
TRACE[02-09|20:30:30.972] Dial error                               task="staticdial dc01bcba00a26ab3 3.11.147.67:30303" err="server stopped"
TRACE[02-09|20:30:30.980] Setting up connection failed             addr=52.56.136.200:30303 err="server stopped"
TRACE[02-09|20:30:30.980] Dial error                               task="staticdial 4a59b0cf444d071d 52.56.136.200:30303" err="server stopped"
TRACE[02-09|20:30:30.995] Setting up connection failed             addr=144.76.236.199:40303 err="server stopped"
TRACE[02-09|20:30:30.995] Dial error                               task="staticdial e80af6c023e27266 144.76.236.199:40303" err="server stopped"
DEBUG[02-09|20:30:32.955] Couldn't add port mapping                proto=tcp extport=30303 intport=30303 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[02-09|20:30:32.955] Deleting port mapping                    proto=tcp extport=30303 intport=30303 interface="UPnP or NAT-PMP"
DEBUG[02-09|20:30:32.955] Couldn't add port mapping                proto=udp extport=30303 intport=30303 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[02-09|20:30:32.955] Deleting port mapping                    proto=udp extport=30303 intport=30303 interface="UPnP or NAT-PMP"

Steps to reproduce the behaviour

This starts with the unstable develop version a903912b as of January 28th. The previous versions worked just fine. This version seems to be the last develop version that works 44c365c3. I do not believe this is an issue with my network as I have been running 100's of geth versions for the past years from this same network. Also if I downgrade to the binary on January 27 things work just fine.

rfikki commented 4 years ago 
DEBUG[02-10|09:41:36.419] Sanitizing Go's GC trigger               percent=100
INFO [02-10|09:41:36.423] Maximum peer count                       ETH=0 LES=10 total=50
DEBUG[02-10|09:41:36.425] FS scan times                            list=0s set=0s diff=0s
TRACE[02-10|09:41:36.463] Handled keystore changes                 time=36.9992ms
INFO [02-10|09:41:36.579] Starting peer-to-peer node               instance=Geth/v1.9.11-unstable-4a231cd9-20200207/windows-amd64/go1.13.6
INFO [02-10|09:41:36.581] Allocated cache and file handles         database=D:\\projects\\ethereum_develop_mainnet_lightclient\\testnet_data\\geth\\lightchaindata cache=512.00MiB handles=8192
INFO [02-10|09:41:37.270] Initialised chain configuration          config="{ChainID: 1 Homestead: 1150000 DAO: 1920000 DAOSupport: true EIP150: 2463000 EIP155: 2675000 EIP158: 2675000 Byzantium: 4370000 Constantinople: 7280000 Petersburg: 7280000 Istanbul: 9069000, Muir Glacier: 9200000, Engine: ethash}"
INFO [02-10|09:41:37.272] Disk storage enabled for ethash caches   dir=D:\\projects\\ethereum_develop_mainnet_lightclient\\testnet_data\\geth\\ethash count=3
INFO [02-10|09:41:37.273] Disk storage enabled for ethash DAGs     dir=C:\\Users\\rfikk\\AppData\\Local\\Ethash count=2
INFO [02-10|09:41:37.307] Added trusted checkpoint                 block=9306111 hash=7da963…f7d0b6
INFO [02-10|09:41:37.307] Loaded most recent local header          number=9338078 hash=42e507…81b1de td=13811908687875144536730 age=2w4d2h
INFO [02-10|09:41:37.339] Configured checkpoint registrar          address=0x9a9070028361F7AAbeB3f2F2Dc07F82C4a98A02a signers=5 threshold=2
DEBUG[02-10|09:41:37.342] Recalculated downloader QoS values       rtt=20s confidence=1.000 ttl=1m0s
DEBUG[02-10|09:41:37.434] TCP listener up                          addr=[::]:30303
DEBUG[02-10|09:41:37.434] UDP listener up                          addr=[::]:30303
INFO [02-10|09:41:37.439] UDP listener up                          net=enode://5538ee9e93b111286032068b60cea629359d3b23472802092ff33a65c40ab3784f514b61d8059080af73e0e6ebf523ae3df9978f7c3a2cdcabd414ac2d183382@[::]:30303
TRACE[02-10|09:41:37.442] <-net.refreshReq 
DEBUG[02-10|09:41:37.443]                                          msg="seed node (age 439263h41m37.4446936s): enode://06051a5573c81934c9554ef2898eb13b33a34b94cf36b202b69fde139ca17a85051979867720d4bdae4323d4943ddf9aeeb6643633aa656e0be843659795007a@35.177.226.168:30303"
TRACE[02-10|09:41:37.444] Pinging remote node                      node=06051a5573c81934
TRACE[02-10|09:41:37.444] >>> nodeEvent(1) to 06051a5573c81934@35.177.226.168:30303 
DEBUG[02-10|09:41:37.445]                                          msg="seed node (age 439263h41m37.4456934s): enode://0cc5f5ffb5d9098c8b8c62325f3797f56509bff942704687b6530992ac706e2cb946b90a34f1f19548cd3c7baccbcaea354531e5983c7d1bc0dee16ce4b6440b@40.118.3.223:30304"
TRACE[02-10|09:41:37.445] Pinging remote node                      node=0cc5f5ffb5d9098c
TRACE[02-10|09:41:37.445] >>> nodeEvent(1) to 0cc5f5ffb5d9098c@40.118.3.223:30304 
DEBUG[02-10|09:41:37.445]                                          msg="seed node (age 439263h41m37.4456934s): enode://1c7a64d76c0334b0418c004af2f67c50e36a3be60b5e4790bdac0439d21603469a85fad36f2473c9a80eb043ae60936df905fa28f1ff614c3e5dc34f15dcd2dc@40.118.3.223:30306"
TRACE[02-10|09:41:37.445] Pinging remote node                      node=1c7a64d76c0334b0
TRACE[02-10|09:41:37.445] >>> nodeEvent(1) to 1c7a64d76c0334b0@40.118.3.223:30306 
DEBUG[02-10|09:41:37.445]                                          msg="seed node (age 439263h41m37.4456934s): enode://85c85d7143ae8bb96924f2b54f1b3e70d8c4d367af305325d30a61385a432f247d2c75c45c6b4a60335060d072d7f5b35dd1d4c45f76941f62a4f83b6e75daaf@40.118.3.223:30307"
TRACE[02-10|09:41:37.446] Pinging remote node                      node=85c85d7143ae8bb9
TRACE[02-10|09:41:37.446] >>> nodeEvent(1) to 85c85d7143ae8bb9@40.118.3.223:30307 
WARN [02-10|09:41:37.446] Light client mode is an experimental feature 
TRACE[02-10|09:41:37.446] <-net.queryReq 
TRACE[02-10|09:41:37.446] <-net.queryReq 
TRACE[02-10|09:41:37.446] <-net.queryReq 
TRACE[02-10|09:41:37.446] <-net.queryReq 
INFO [02-10|09:41:37.448] New local node record                    seq=21 id=211f27d3213d668f ip=127.0.0.1 udp=30303 tcp=30303
INFO [02-10|09:41:37.448] Started P2P networking                   self=enode://5538ee9e93b111286032068b60cea629359d3b23472802092ff33a65c40ab3784f514b61d8059080af73e0e6ebf523ae3df9978f7c3a2cdcabd414ac2d183382@127.0.0.1:30303
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=d3df0650484ee538 fails=161 conn=0.011904761904761904/168 delay=115.78031ms/4705 response=28.612062ms/2572 timeout=0/2572
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=9e93d3e5dc0cb167 fails=151 conn=0.013071895424836602/153 delay=77.156422ms/4705 response=104.059922ms/1564 timeout=0.027967681789931635/1609
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=d5b4741a4cca30f5 fails=148 conn=0.013333333333333334/150 delay=205.021694ms/4705 response=142.925101ms/435  timeout=0.01583710407239819/442
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=d655c2873060ec63 fails=77  conn=0.0076045627376425855/263 delay=1.077236076s/4705 response=169.960765ms/335  timeout=0.02616279069767442/344
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=8538f1370bd8eb8d fails=141 conn=0.006619188928431372/170  delay=8.571428571s/7    response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=8c87dda2213f1268 fails=133 conn=0.011235955056179775/178  delay=814.547189ms/3499 response=180.265987ms/124  timeout=0.10144927536231885/138
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=32ab2e8a9fdadc72 fails=131 conn=0.01313847722045855/378   delay=2.575493186s/701  response=248.571065ms/32   timeout=0.030303030303030304/33
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=8e3aa2776ff5a770 fails=151 conn=0.0027402125876712334/365 delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=a8dfb6e02d9bfebf fails=0   conn=0.022748017558114033/152  delay=82.255723ms/395   response=329.136915ms/19   timeout=0.9166666666666666/228
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=d850981575d8b4c4 fails=154 conn=0.011363862336489899/264  delay=4.415698827s/165  response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=28ef2de400bed6bf fails=126 conn=0.0149812734082397/267    delay=9.996896337s/3222 response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=dae27c026b72b25f fails=8   conn=0.009093249131202142/2002 delay=659.179059ms/660  response=162.9052ms/8      timeout=0.813953488372093/43
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=e0f7a02a46d7c52a fails=0   conn=0.012587716869379768/1179.1097408303333 delay=1.184765475s/505  response=88.149ms/2        timeout=0.8/10
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=2ce013f73006417a fails=91  conn=0.016030669750813013/820                delay=624.284839ms/669  response=263.123642ms/59   timeout=0.37894736842105264/95
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=5ef3c1f758f77774 fails=4   conn=0.015986797023933103/1156               delay=1.471025355s/637  response=0s/1              timeout=0.8571428571428571/7
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=31e5e7c0ae800d8f fails=12  conn=0.0698797355473343/87.39419372916666    delay=9.955517898s/4721 response=392.646409ms/11   timeout=0.8103448275862069/58
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=e80830a4c045a0ab fails=0   conn=0.1771498353625495/34.268921092         delay=4.369380352s/4699 response=111.456275ms/4    timeout=0.8518518518518519/27
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=cc727ccccc52e3e2 fails=0   conn=0.012848643276334228/374.09460620016665 delay=1.28226778s/127   response=190.01815ms/4     timeout=0.7777777777777778/18
DEBUG[02-10|09:41:37.452] Loaded server stats                      id=e6547bab122459ee fails=142 conn=0.010488846872752039/210.01941129066665 delay=9.99334664s/1503  response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=c8d04aab2d6e9d35 fails=137 conn=0.02702076866651139/658.1443865451666   delay=9.648883047s/2487 response=144.678045ms/2033 timeout=0.012147716229348883/2058
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=7c7722b6fc35a14a fails=58  conn=0.015072826845238096/70                 delay=0s/4              response=0s/1              timeout=0.6666666666666666/3
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=413f85c877b95d6f fails=98  conn=0.03700611537571745/755                 delay=9.75347908s/4034  response=317.459805ms/1595 timeout=0.22535211267605634/2059
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=2b3503e66de1a8ba fails=54  conn=0.0913501245591398/93                   delay=9.998321302s/5957 response=0s/1              timeout=0.6666666666666666/3
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=6d2c66d4f1e9b406 fails=137 conn=0.009216589861751152/217                delay=9.989583333s/960  response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=cddce9ec6a78ab12 fails=82  conn=0.01905524766736402/239                 delay=121.772392ms/1197 response=170.416189ms/348  timeout=0.01971830985915493/355
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=e48a8fa0d74713ed fails=139 conn=0.00727283573030303/275                 delay=9.882352941s/85   response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=e83c200b4ce23611 fails=30  conn=0.14447207934771103/63.52600703266667   delay=9.998282082s/5821 response=0s/1              timeout=0.75/4
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=65761de4b87c3536 fails=142 conn=0.01048442401829871/337                 delay=9.926470588s/136  response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=7cc23780acd19d17 fails=0   conn=0.04099945050104818/636                 delay=457.094749ms/1099 response=0s/1              timeout=0.9879518072289156/83
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=b60ffa60e688f3c6 fails=93  conn=0.0037593984962406013/532               delay=9.6875s/32        response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=063d0931cddfa50e fails=130 conn=0.014598540145985401/137                delay=9.838709677s/62   response=161.826155ms/1116 timeout=0/1116
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=af905f480df310b2 fails=153 conn=0.028248080208333328/336                delay=123.745692ms/528  response=97.284364ms/203   timeout=0.08558558558558559/222
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=32d2dae0e40a74a3 fails=144 conn=0.012422360248447204/161                delay=9.955357142s/224  response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=5b7ad2a05963f56e fails=83  conn=0.0035768746229749605/679               delay=684.539504ms/65   response=277.111418ms/239  timeout=0.3248587570621469/354
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=f23ac6da7c02f84a fails=123 conn=0.02202011603110048/209                 delay=1.264826ms/1548   response=50.406771ms/1677  timeout=0.002379535990481856/1681
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=009be51d1fc4aa23 fails=90  conn=0.03386875377689243/502                 delay=2.086208146s/3067 response=156.979536ms/19   timeout=0.4722222222222222/36
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=e72e5527face59bb fails=4   conn=0.03430394935931052/757.639830498       delay=100.715341ms/2003 response=381.607398ms/53   timeout=0.924822695035461/705
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=930cf49cd4de09a6 fails=117 conn=0.006864395662842588/2092               delay=967.28611ms/3286  response=160.649562ms/884  timeout=0.04638619201725998/927
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=e2e7d66dd1c59600 fails=117 conn=0.026756056698080278/191                delay=10.015234ms/2373  response=137.169328ms/3332 timeout=0.13274336283185842/3842
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=242254cc4c1d43a5 fails=76  conn=0.008599303261904761/126                delay=5s/2              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=b7e675d1b725f538 fails=110 conn=0.007962525609182938/461                delay=627.755µs/137     response=87.939137ms/108   timeout=0.01818181818181818/110
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=655abf31d8960210 fails=93  conn=0.011660281737681159/115                delay=0s/15             response=126.927871ms/7    timeout=0/7
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=71563f2370599df6 fails=81  conn=0.010801963549707602/114                delay=0s/12             response=116.370355ms/9    timeout=0/9
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=0d5c31db1f6f959a fails=100 conn=0.00782078893690476/140                 delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=35e69c239d0e3944 fails=82  conn=0.012135049554347825/92                 delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=6085df138bc6b494 fails=77  conn=0.005150773426282053/208                delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=8165b744701daad7 fails=90  conn=0.0025054973132861654/424               delay=0s/8              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=0bd3496a30c655cc fails=33  conn=0.005494880233516484/182                delay=0s/2              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=2d1f1ff277435247 fails=26  conn=0.011277398732389253/918                delay=969.582999ms/1216 response=129.969744ms/876  timeout=0/876
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=09b73c91a98e5881 fails=6   conn=0.015873015873015872/126                delay=6.022304276s/151  response=64.45445ms/2      timeout=0.3333333333333333/3
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=1e1ea8b3d566d276 fails=12  conn=0.012536790164149889/596                delay=2.281671594s/690  response=304.325476ms/128  timeout=0.26436781609195403/174
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=2842143af96500ac fails=20  conn=0.0011787592985865736/849               delay=0s/24             response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=8d723daac527a6b7 fails=19  conn=0.003809708922686946/263                delay=0s/3              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=6ed536e072b74f0f fails=4   conn=0.09459835116666665/140                 delay=47.591759ms/994   response=260.722117ms/515  timeout=0.3513853904282116/794
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=a5a3635a2e61cffe fails=0   conn=0.0007239037635160677/2645              delay=1.079916825s/55   response=115.1051ms/4      timeout=0.7647058823529411/17
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=2f2cbb4523b32e34 fails=6   conn=0.012809550523053662/1323               delay=5.184619776s/590  response=0s/1              timeout=0.9090909090909091/11
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=74df075b0a2b5fca fails=10  conn=0.07655808774404763/28                  delay=2.887007805s/136  response=176.49955ms/2     timeout=0/2
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=ade351b75c2bc03e fails=8   conn=0.06789270247916666/16                  delay=0s/6              response=118.533733ms/6    timeout=0/6
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=0c6253589a8d244d fails=7   conn=0.0034916175890132247/983               delay=3.468618907s/503  response=148.96665ms/275   timeout=0.46078431372549017/510
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=32f7e89d30e83b68 fails=4   conn=0.02033867097521368/195                 delay=0s/310            response=169.590135ms/289  timeout=0.049342105263157895/304
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=7459dfca2c2a3114 fails=1   conn=0.0011337650150025599/3255              delay=9.88095238s/84    response=68.5005ms/2       timeout=0.8947368421052632/19
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=a163353e97c59e55 fails=0   conn=0.028713547440821257/138                delay=104.736816ms/1330 response=181.401262ms/3020 timeout=0.022653721682847898/3090
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=5c5f80d8723be804 fails=6   conn=0.018519151490740744/108                delay=604.135099ms/255  response=144.434854ms/55   timeout=0/55
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=2097603f3e07429b fails=0   conn=0.4/10                                  delay=129.578333ms/3260 response=258.289038ms/656  timeout=0.4339948231233822/1159
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=0cdf4a93328f21e6 fails=0   conn=0.006187315755361122/1943               delay=2.682510771s/362  response=255.462117ms/1724 timeout=0.05843801201529219/1831
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=14a4e05b000de89d fails=2   conn=0.015626591414062502/64                 delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Loaded server stats                      id=955d805795801a31 fails=0   conn=0.0040816599292517/245                  delay=0s/1              response=0s/1              timeout=0/1
DEBUG[02-10|09:41:37.453] Dialing new peer                         lesaddr=74df075b0a2b5fca21cdd5f39f6018782493a053d905060483662b80ca3c9114@52.196.62.203:30303 set=1  known=true
DEBUG[02-10|09:41:37.454] Dialing new peer                         lesaddr=955d805795801a313f4b4d92e7548941bffe92d651d25696d67e1becea115218@3.13.95.6:30303 set=1  known=true
DEBUG[02-10|09:41:37.454] Dialing new peer                         lesaddr=14a4e05b000de89dcd7d7d493ce99cd375523ed378420a16996860d1b95604f8@175.45.48.134:30393 set=1  known=true
TRACE[02-10|09:41:37.454] Adding static node                       node=enode://2679fae137c233712dc71c3e6f0f7345c5889e511c836e1ac1cc7b0232f1f2b6b07abb5f616e9ad9139b715d270c5df450b562d189ef9b7ddc7205dbc9aed339@52.196.62.203:30303
TRACE[02-10|09:41:37.454] New dial task                            task="staticdial 74df075b0a2b5fca 52.196.62.203:30303"
TRACE[02-10|09:41:37.455] Adding static node                       node=enode://1595cc1212354d52497ef247a69fb8b97f60a5f70812010c09310f93151445cd6c0aae423fb3b4314e0d269e6edfc897d4ee054d6b60050ca77cea6fc64434e2@3.13.95.6:30303
TRACE[02-10|09:41:37.455] New dial task                            task="staticdial 955d805795801a31 3.13.95.6:30303"
TRACE[02-10|09:41:37.455] Adding static node                       node=enode://dd8adee8d71b65624776d9f7da20b637abfcef0279d52ff31f0aac487479d2328e23e2b9072dc185c2c71cebb74782a38fb37feacc91b849f5517954e042ccf0@175.45.48.134:30393
TRACE[02-10|09:41:37.455] New dial task                            task="staticdial 14a4e05b000de89d 175.45.48.134:30393"
INFO [02-10|09:41:37.454] started whisper v.6.0 
INFO [02-10|09:41:37.469] GraphQL endpoint opened                  url=http://127.0.0.1:8547
DEBUG[02-10|09:41:37.471] InProc registered                        namespace=admin
DEBUG[02-10|09:41:37.471] InProc registered                        namespace=admin
DEBUG[02-10|09:41:37.472] InProc registered                        namespace=debug
DEBUG[02-10|09:41:37.472] InProc registered                        namespace=web3
DEBUG[02-10|09:41:37.472] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=txpool
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=debug
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=debug
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=personal
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=ethash
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.473] InProc registered                        namespace=eth
DEBUG[02-10|09:41:37.474] InProc registered                        namespace=net
DEBUG[02-10|09:41:37.474] InProc registered                        namespace=les
DEBUG[02-10|09:41:37.474] InProc registered                        namespace=shh
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=admin
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=admin
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=debug
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=web3
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=txpool
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=debug
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=debug
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=personal
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=ethash
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.474] IPC registered                           namespace=eth
DEBUG[02-10|09:41:37.475] IPC registered                           namespace=net
DEBUG[02-10|09:41:37.475] IPC registered                           namespace=les
DEBUG[02-10|09:41:37.475] IPC registered                           namespace=shh
INFO [02-10|09:41:37.476] IPC endpoint opened                      url=\\\\.\\pipe\\geth.ipc
INFO [02-10|09:41:37.476] IPC endpoint closed                      url=\\\\.\\pipe\\geth.ipc
DEBUG[02-10|09:41:37.476] RPC server shutting down 
DEBUG[02-10|09:41:37.476] RPC server shutting down 
INFO [02-10|09:41:37.476] Blockchain manager stopped 
DEBUG[02-10|09:41:37.476] Reset ancient limit to zero 
INFO [02-10|09:41:37.476] Transaction pool stopped 
TRACE[02-10|09:41:37.476] Ethash remote sealer is exiting 
INFO [02-10|09:41:37.519] Light ethereum stopped 
INFO [02-10|09:41:37.519] whisper stopped 
INFO [02-10|09:41:37.520] GraphQL endpoint closed                  url=http://127.0.0.1:8547
DEBUG[02-10|09:41:37.520] Read error                               err="accept tcp [::]:30303: use of closed network connection"
TRACE[02-10|09:41:37.520] P2P networking is spinning down 
DEBUG[02-10|09:41:37.520] Read error: read udp [::]:30303: use of closed network connection 
TRACE[02-10|09:41:37.520] <-net.closeReq 
TRACE[02-10|09:41:37.520] loop stopped 
DEBUG[02-10|09:41:37.520] shutting down 
TRACE[02-10|09:41:37.530] Rejected peer                            id=955d805795801a31 addr=3.13.95.6:30303 conn=staticdial                              err="server stopped"
TRACE[02-10|09:41:37.530] Setting up connection failed             addr=3.13.95.6:30303 err="server stopped"
TRACE[02-10|09:41:37.530] Dial error                               task="staticdial 955d805795801a31 3.13.95.6:30303" err="server stopped"
TRACE[02-10|09:41:37.638] Setting up connection failed             addr=52.196.62.203:30303 err="server stopped"
TRACE[02-10|09:41:37.638] Dial error                               task="staticdial 74df075b0a2b5fca 52.196.62.203:30303" err="server stopped"
TRACE[02-10|09:41:37.699] Setting up connection failed             addr=175.45.48.134:30393 err="server stopped"
TRACE[02-10|09:41:37.699] Dial error                               task="staticdial 14a4e05b000de89d 175.45.48.134:30393" err="server stopped"
DEBUG[02-10|09:41:39.539] Couldn't add port mapping                proto=tcp extport=30303 intport=30303 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[02-10|09:41:39.539] Deleting port mapping                    proto=tcp extport=30303 intport=30303 interface="UPnP or NAT-PMP"
DEBUG[02-10|09:41:39.539] Couldn't add port mapping                proto=udp extport=30303 intport=30303 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[02-10|09:41:39.539] Deleting port mapping                    proto=udp extport=30303 intport=30303 interface="UPnP or NAT-PMP"
holiman commented 4 years ago

I don't quite understand if this an issue that affects anything? As I understand it (which may be wrong) -- you are trying to shut down geth, and while geth is shutting down, it's showing you some error messages?

holiman commented 4 years ago

Or does the node shut itself down during the boot-up process?

rfikki commented 4 years ago

The node shuts off during the boot-up process. The above are the logs when trying to start the node, Which results in the node shutting down during the boot-up. I am NOT trying to shut down geth. This happens at boot-up. This issue started with the develop version binaries as of Jan 28th. Any binaries before that date work just fine. https://geth.ethereum.org/downloads/

rfikki commented 4 years ago

I believe the changes made to the code here might be causing the issue: https://github.com/ethereum/go-ethereum/commit/a903912b9622780a7b6d852a21307a8a81962fd7

holiman commented 4 years ago

Ah, I have a hunch.. what are your command line options? 

rfikki commented 4 years ago

On further review something in this line of code used as part of the startup options seems to be causing the issue. --rpcapi "admin,db,eth,debug,miner,net,shh,txpool,personal,web3" ^

When I remove that line the node starts up as expected.

rfikki commented 4 years ago

I have been using those options for a long time. Has something changed? Am I using an API/module that has been deprecated? If so, I am sure others will run into this same issue. If it is caused by those options. It would be nice to have an error message that is more verbose as to the issue.

holiman commented 4 years ago

Yep, try removing shh maybe?

rfikki commented 4 years ago

Nope, the issue seems to be with using more than one flag with --rpcapi. It seems there must be an issue with that code in commit a903912. It seems it rejects the comma "," after the first flag in that list. It will only accept one flag as part of the option. This works --rpcapi "admin" ^ anytime you add a comma and second flag it shuts down. This does not work --rpcapi "admin,db" ^

holiman commented 4 years ago

So, what happens for me is 

ERROR[02-12|17:49:02.335] Failed to enumerate USB devices          hub=trezor vendor=21324 failcount=3 err="failed to initialize libusb: libusb: unknown error [code -99]"
Fatal: Error starting protocol stack: invalid API "shh" in whitelist (available: admin, debug, web3, eth, txpool, personal, ethash, miner, net)

BUT, the Fatal: Error starting protocol stack: invalid API "foobar" in whitelist (available: admin, debug, web3, eth, txpool, personal, ethash, miner, net) is sent to stdout, not stderr, where the rest of all logging is sent, so I guess that's why you don't see it.

@fjl perhaps we should do an log.Error at an earlier stage, when we start erroring out and shutting down the node?

holiman commented 4 years ago

Nope, the issue seems to be with using more than one flag with --rpcapi. It seems there must be an issue with that code in commit a903912. It seems it rejects the comma "," after the first flag in that list. It will only accept one flag as part of the option. This works --rpcapi "admin" ^ anytime you add a comma and second flag it shuts down. This does not work --rpiapi "admin,db" ^

Available: admin, debug, web3, eth, txpool, personal, ethash, miner, net Others, like db, shh are now gone. No problems with comma-concatenation so long as you only use the available ones.

rfikki commented 4 years ago

Okay, let me try

rfikki commented 4 years ago

Just tried --rpcapi "admin, miner" ^

The above does not work in windows.

If I do --rpcapi "admin" ^ or rpcapi "miner" ^ they work

It seems comma-concatenation may be the issue for me.

holiman commented 4 years ago

This works for me (with space after comma):

build/bin/geth --dev --rpc --rpcapi "admin, miner"

as well as no space:

build/bin/geth --dev --rpc --rpcapi="admin,miner"

Can you confirm whether these exact two commands work or not for you?

holiman commented 4 years ago

And also provide the exact output that the "Fatal: Error starting protocol stack: ..." prints?

rfikki commented 4 years ago

build/bin/geth --dev --rpc --rpcapi "admin, miner" as well as no space: build/bin/geth --dev --rpc --rpcapi="admin,miner"

Do not work for me. Like I said as soon as I add the comma and second flag it does not work. I am using windows 10.

holiman commented 4 years ago

Two odd things here:

  1. That it doesn't work the way it should, with flag-parsing
  2. That you don't get the output line Fatal: Error starting protocol stack..., which should tell you exactly what goes wrong with the parsing
rfikki commented 4 years ago

Turns out I got this to work.

After much trial and error and by eliminating (miner and ethash) from the options. Not sure why it won't accept miner and/or ethash.

These options work: --rpcapi "admin, debug, web3, personal, net, eth, txpool" ^

adamschmideg commented 4 years ago

Next step is to merge a PR that writes error messages to the log.

rfikki commented 4 years ago

So, lessons learned from this issue. Log messages needs to be improved in two ways.

1) When running in light node mode the "miner" and "ethash" rpc api options cannot be used. Need a better error message when dealing with these issues.

2) If and when using an external drive as the --datadir.ancient should windows arbitrarily at some point change the drive letter from say F:/ to G:/ there is no log message that tells you about this issue when running node boot up from a script. This can happen due to windows upgrade/update, as well as unplugging from the USB. When this happens the boot-up just silently dies, no error message to signify that the directory is not accessible.

holiman commented 4 years ago

So the two commands I asked you to try, and confirm, and you said you did -- am I to understand that you simply did not run them? 

rfikki commented 4 years ago

I ran the two commands you provided. See my response above. Unfortunately the command you proposed contained the "miner" flag. I guess since I was running the node in light mode it would not work.

It seems available modules in light mode are different, only these are available. modules: admin:1.0 clique:1.0 debug:1.0 eth:1.0 les:1.0 net:1.0 personal:1.0 rpc:1.0 shh:1.0 txpool:1.0 web3:1.0

fjl commented 4 years ago

I think we should turn the startup error into a warning to fix this issue. This new check has already bitten us two times since it was merged, and it's very hard to understand what's wrong when it happens.

holiman commented 4 years ago

I ran the two commands you provided. See my response above. Unfortunately the command you proposed contained the "miner" flag. I guess since I was running the node in light mode it would not work.

No, you did not, since my command did not include syncmode=light. You ran something else, and it would have been appropriate to provide that information. Closing this since it's resolved

rfikki commented 4 years ago

Dude, you are bananas.

rfikki commented 4 years ago

You can plainly see in the error log I submitted that it was in light mode. I find your accusatory tone lacking in civility. if you expect users to submit issues with this type of response you are mistaken.

fjl commented 4 years ago

This was actually not resolved. But the RPC service issue should be resolved in https://github.com/ethereum/go-ethereum/pull/20684 which I just opened.

fjl commented 4 years ago

We should find a solution for the inaccessible datadir issue.

fjl commented 4 years ago

About printing the "Fatal: ..." error: geth is actually trying to be smart about this

https://github.com/ethereum/go-ethereum/blob/57d4898e2992a46fc2deab93a2666a2979b6704c/cmd/utils/cmd.go#L46-L55

i.e. it prints to BOTH stdout and stderr, but that doesn't work on Windows for some reason. We should probably change it to print only to stderr instead.

fjl commented 4 years ago

The original issue is now solved in a released version. Instead of failing to start up when unavailable APIs are whitelisted, we now log a warning message. We cannot fix the printing of the Fatal: ... message on windows unfortunately. I looked into it a bit and couldn't find a way to detect if stderr is redirected.