From 80c4925ff0ab4b6acc3a5d4223bd47fd9e636a21 Mon Sep 17 00:00:00 2001 From: Gav Wood Date: Thu, 24 Jul 2014 23:38:56 +0200 Subject: [PATCH] Additional alterations to network & logging for ease of debugging. --- alethzero/Main.ui | 14 ++++---- alethzero/MainWin.cpp | 43 ++++++++++++++++++------- alethzero/MainWin.h | 3 ++ libethereum/Client.cpp | 26 +++++++++++---- libethereum/Client.h | 3 ++ libethereum/PeerNetwork.h | 13 ++++---- libethereum/PeerServer.cpp | 22 +++++++------ libethereum/PeerServer.h | 2 +- libethereum/PeerSession.cpp | 64 ++++++++++++++++++++++++------------- libethereum/PeerSession.h | 2 ++ libqethereum/QEthereum.h | 2 +- 11 files changed, 130 insertions(+), 64 deletions(-) diff --git a/alethzero/Main.ui b/alethzero/Main.ui index 4ccdab651..b5bb04df6 100644 --- a/alethzero/Main.ui +++ b/alethzero/Main.ui @@ -377,19 +377,21 @@ 0 - + - Monospace - 12 + Ubuntu Mono - - Qt::NoFocus - QFrame::NoFrame + + QFrame::Plain + + + 0 + diff --git a/alethzero/MainWin.cpp b/alethzero/MainWin.cpp index f55fc4525..1e0eb3c74 100644 --- a/alethzero/MainWin.cpp +++ b/alethzero/MainWin.cpp @@ -124,7 +124,15 @@ Main::Main(QWidget *parent) : { setWindowFlags(Qt::Window); ui->setupUi(this); - g_logPost = [=](std::string const& s, char const* c) { simpleDebugOut(s, c); ui->log->addItem(QString::fromStdString(s)); }; + g_logPost = [=](std::string const& s, char const* c) + { + simpleDebugOut(s, c); + m_logLock.lock(); + m_logHistory.append(QString::fromStdString(s) + "\n"); + m_logChanged = true; + m_logLock.unlock(); +// ui->log->addItem(QString::fromStdString(s)); + }; #if 0&Ð_DEBUG m_servers.append("192.168.0.10:30301"); @@ -279,7 +287,7 @@ void Main::installBalancesWatch() void Main::onNameRegChange() { - cdebug << "NameReg changed!"; + cwatch << "NameReg changed!"; // update any namereg-dependent stuff - for now force a full update. refreshAll(); @@ -287,7 +295,7 @@ void Main::onNameRegChange() void Main::onCurrenciesChange() { - cdebug << "Currencies changed!"; + cwatch << "Currencies changed!"; installBalancesWatch(); // TODO: update any currency-dependent stuff? @@ -295,14 +303,14 @@ void Main::onCurrenciesChange() void Main::onBalancesChange() { - cdebug << "Our balances changed!"; + cwatch << "Our balances changed!"; refreshBalances(); } void Main::onNewBlock() { - cdebug << "Blockchain changed!"; + cwatch << "Blockchain changed!"; // update blockchain dependent views. refreshBlockCount(); @@ -312,7 +320,7 @@ void Main::onNewBlock() void Main::onNewPending() { - cdebug << "Pending transactions changed!"; + cwatch << "Pending transactions changed!"; // update any pending-transaction dependent views. refreshPending(); @@ -608,6 +616,7 @@ void Main::refreshMining() void Main::refreshBalances() { + cwatch << "refreshBalances()"; // update all the balance-dependent stuff. ui->ourAccounts->clear(); u256 totalBalance = 0; @@ -660,7 +669,7 @@ void Main::refreshAll() void Main::refreshPending() { - cdebug << "refreshPending()"; + cwatch << "refreshPending()"; ui->transactionQueue->clear(); for (Transaction const& t: m_client->pending()) { @@ -682,7 +691,7 @@ void Main::refreshPending() void Main::refreshAccounts() { - cdebug << "refreshAccounts()"; + cwatch << "refreshAccounts()"; ui->accounts->clear(); ui->contracts->clear(); for (auto n = 0; n < 2; ++n) @@ -703,7 +712,7 @@ void Main::refreshAccounts() void Main::refreshDestination() { - cdebug << "refreshDestination()"; + cwatch << "refreshDestination()"; QString s; for (auto i: m_client->addresses()) if ((s = pretty(i)).size()) @@ -717,7 +726,7 @@ void Main::refreshDestination() void Main::refreshBlockCount() { - cdebug << "refreshBlockCount()"; + cwatch << "refreshBlockCount()"; auto d = m_client->blockChain().details(); auto diff = BlockInfo(m_client->blockChain().block()).difficulty; ui->blockCount->setText(QString("#%1 @%3 T%2 N%4 D%5").arg(d.number).arg(toLog2(d.totalDifficulty)).arg(toLog2(diff)).arg(eth::c_protocolVersion).arg(eth::c_databaseVersion)); @@ -750,7 +759,7 @@ static bool transactionMatch(string const& _f, Transaction const& _t) void Main::refreshBlockChain() { - cdebug << "refreshBlockChain()"; + cwatch << "refreshBlockChain()"; eth::ClientGuard g(m_client.get()); auto const& st = state(); @@ -834,6 +843,15 @@ void Main::timerEvent(QTimerEvent*) if (interval / 100 % 2 == 0) refreshMining(); + if (m_logChanged) + { + m_logLock.lock(); + m_logChanged = false; + ui->log->appendPlainText(m_logHistory); + m_logHistory.clear(); + m_logLock.unlock(); + } + // refresh peer list every 1000ms, reset counter if (interval == 1000) { @@ -1198,7 +1216,8 @@ void Main::on_ourAccounts_doubleClicked() void Main::on_log_doubleClicked() { - qApp->clipboard()->setText(ui->log->currentItem()->text()); + ui->log->setPlainText(""); + m_logHistory.clear(); } void Main::on_accounts_doubleClicked() diff --git a/alethzero/MainWin.h b/alethzero/MainWin.h index 7117618ea..35f8cb137 100644 --- a/alethzero/MainWin.h +++ b/alethzero/MainWin.h @@ -229,6 +229,9 @@ private: QNetworkAccessManager m_webCtrl; QList> m_consoleHistory; + QMutex m_logLock; + QString m_logHistory; + bool m_logChanged = true; QEthereum* m_ethereum = nullptr; }; diff --git a/libethereum/Client.cpp b/libethereum/Client.cpp index df5df27b5..d2905234d 100644 --- a/libethereum/Client.cpp +++ b/libethereum/Client.cpp @@ -131,7 +131,7 @@ unsigned Client::installWatch(h256 _h) { auto ret = m_watches.size() ? m_watches.rbegin()->first + 1 : 0; m_watches[ret] = Watch(_h); - cdebug << "Install watch" << ret << _h; + cwatch << "+++" << ret << _h; return ret; } @@ -149,7 +149,7 @@ unsigned Client::installWatch(TransactionFilter const& _f) void Client::uninstallWatch(unsigned _i) { - cdebug << "Uninstall watch" << _i; + cwatch << "XXX" << _i; lock_guard l(m_filterLock); @@ -189,7 +189,7 @@ void Client::noteChanged(h256Set const& _filters) for (auto& i: m_watches) if (_filters.count(i.second.id)) { - cdebug << "Watch activated" << i.first << i.second.id; + cwatch << "!!!" << i.first << i.second.id; i.second.changes++; } } @@ -262,7 +262,7 @@ void Client::transact(Secret _secret, u256 _value, Address _dest, bytes const& _ ClientGuard l(this); Transaction t; - cdebug << "Nonce at " << toAddress(_secret) << " pre:" << m_preMine.transactionsFrom(toAddress(_secret)) << " post:" << m_postMine.transactionsFrom(toAddress(_secret)); +// cdebug << "Nonce at " << toAddress(_secret) << " pre:" << m_preMine.transactionsFrom(toAddress(_secret)) << " post:" << m_postMine.transactionsFrom(toAddress(_secret)); t.nonce = m_postMine.transactionsFrom(toAddress(_secret)); t.value = _value; t.gasPrice = _gasPrice; @@ -302,6 +302,7 @@ void Client::inject(bytesConstRef _rlp) void Client::work(bool _justQueue) { + cdebug << ">>> WORK"; h256Set changeds; // Process network events. @@ -309,11 +310,14 @@ void Client::work(bool _justQueue) // Will broadcast any of our (new) transactions and blocks, and collect & add any of their (new) transactions and blocks. if (m_net && !_justQueue) { + cdebug << "--- WORK: LOCK"; ClientGuard l(this); + cdebug << "--- WORK: NETWORK"; m_net->process(); // must be in guard for now since it uses the blockchain. - // TODO: return h256Set as block hashes, once for each block that has come in/gone out. - h256Set newBlocks = m_net->sync(m_bc, m_tq, m_stateDB); + // returns h256Set as block hashes, once for each block that has come in/gone out. + cdebug << "--- WORK: TQ <== NET ==> CHAIN"; + h256Set newBlocks = m_net->sync(m_bc, m_tq, m_stateDB, 100); if (newBlocks.size()) { for (auto i: newBlocks) @@ -353,6 +357,7 @@ void Client::work(bool _justQueue) if (m_doMine) { + cdebug << "--- WORK: MINE"; m_restartMining = false; // Mine for a while. @@ -368,7 +373,9 @@ void Client::work(bool _justQueue) if (mineInfo.completed) { // Import block. + cdebug << "--- WORK: COMPLETE MINE%"; m_postMine.completeMine(); + cdebug << "--- WORK: CHAIN <== postSTATE"; h256s hs = m_bc.attemptImport(m_postMine.blockData(), m_stateDB); if (hs.size()) { @@ -380,7 +387,10 @@ void Client::work(bool _justQueue) } } else + { + cdebug << "--- WORK: SLEEP"; this_thread::sleep_for(chrono::milliseconds(100)); + } } // Synchronise state to block chain. @@ -392,6 +402,7 @@ void Client::work(bool _justQueue) // Resynchronise state with block chain & trans { ClientGuard l(this); + cdebug << "--- WORK: preSTATE <== CHAIN"; if (m_preMine.sync(m_bc) || m_postMine.address() != m_preMine.address()) { if (m_doMine) @@ -402,6 +413,7 @@ void Client::work(bool _justQueue) } // returns h256s as blooms, once for each transaction. + cdebug << "--- WORK: postSTATE <== TQ"; h256s newPendingBlooms = m_postMine.sync(m_tq); if (newPendingBlooms.size()) { @@ -415,7 +427,9 @@ void Client::work(bool _justQueue) } } + cdebug << "--- WORK: noteChanged" << changeds.size() << "items"; noteChanged(changeds); + cdebug << "<<< WORK"; } void Client::lock() const diff --git a/libethereum/Client.h b/libethereum/Client.h index b1089741c..d589d30ce 100644 --- a/libethereum/Client.h +++ b/libethereum/Client.h @@ -157,6 +157,9 @@ struct Watch unsigned changes = 1; }; +struct WatchChannel: public LogChannel { static const char* name() { return "(o)"; } static const int verbosity = 6; }; +#define cwatch eth::LogOutputStream() + /** * @brief Main API hub for interfacing with Ethereum. */ diff --git a/libethereum/PeerNetwork.h b/libethereum/PeerNetwork.h index 7f6b00b5d..22ebd98b7 100644 --- a/libethereum/PeerNetwork.h +++ b/libethereum/PeerNetwork.h @@ -46,12 +46,13 @@ class PeerSession; struct NetWarn: public LogChannel { static const char* name() { return "!N!"; } static const int verbosity = 0; }; struct NetNote: public LogChannel { static const char* name() { return "*N*"; } static const int verbosity = 1; }; struct NetMessageSummary: public LogChannel { static const char* name() { return "-N-"; } static const int verbosity = 2; }; -struct NetMessageDetail: public LogChannel { static const char* name() { return "=N="; } static const int verbosity = 3; }; -struct NetTriviaSummary: public LogChannel { static const char* name() { return "-N-"; } static const int verbosity = 4; }; -struct NetTriviaDetail: public LogChannel { static const char* name() { return "=N="; } static const int verbosity = 5; }; -struct NetAllDetail: public LogChannel { static const char* name() { return "=N="; } static const int verbosity = 6; }; -struct NetRight: public LogChannel { static const char* name() { return ">N>"; } static const int verbosity = 8; }; -struct NetLeft: public LogChannel { static const char* name() { return "N>"; } static const int verbosity = 18; }; +struct NetLeft: public LogChannel { static const char* name() { return "async_connect(_ep, [=](boost::system::error_code const& ec) { if (ec) { - clog(NetNote) << "Connection refused to " << _ep << " (" << ec.message() << ")"; + clog(NetConnect) << "Connection refused to " << _ep << " (" << ec.message() << ")"; for (auto i = m_incomingPeers.begin(); i != m_incomingPeers.end(); ++i) if (i->second.first == _ep && i->second.second < 3) { @@ -323,13 +323,13 @@ void PeerServer::connect(bi::tcp::endpoint const& _ep) goto OK; } // for-else - clog(NetNote) << "Giving up."; + clog(NetConnect) << "Giving up."; OK:; } else { auto p = make_shared(this, std::move(*s), m_networkId, _ep.address(), _ep.port()); - clog(NetNote) << "Connected to " << _ep; + clog(NetConnect) << "Connected to " << _ep; p->start(); } delete s; @@ -363,7 +363,7 @@ bool PeerServer::noteBlock(h256 _hash, bytesConstRef _data) return false; } -h256Set PeerServer::sync(BlockChain& _bc, TransactionQueue& _tq, OverlayDB& _o) +h256Set PeerServer::sync(BlockChain& _bc, TransactionQueue& _tq, OverlayDB& _o, unsigned _max) { h256Set ret; @@ -427,12 +427,13 @@ h256Set PeerServer::sync(BlockChain& _bc, TransactionQueue& _tq, OverlayDB& _o) } m_latestBlockSent = h; - for (int accepted = 1, n = 0; accepted; ++n) + unsigned totalAccepted = 0; + for (int accepted = 1, n = 0; accepted && totalAccepted < _max; ++n) { accepted = 0; lock_guard l(m_incomingLock); if (m_incomingBlocks.size()) - for (auto it = prev(m_incomingBlocks.end());; --it) + for (auto it = prev(m_incomingBlocks.end()); totalAccepted < _max; --it) { try { @@ -440,6 +441,7 @@ h256Set PeerServer::sync(BlockChain& _bc, TransactionQueue& _tq, OverlayDB& _o) ret.insert(h); it = m_incomingBlocks.erase(it); ++accepted; + ++totalAccepted; netChange = true; } catch (UnknownParent) diff --git a/libethereum/PeerServer.h b/libethereum/PeerServer.h index 0eae35a1f..465a4dc41 100644 --- a/libethereum/PeerServer.h +++ b/libethereum/PeerServer.h @@ -58,7 +58,7 @@ public: void connect(bi::tcp::endpoint const& _ep); /// Sync with the BlockChain. It might contain one of our mined blocks, we might have new candidates from the network. - h256Set sync(BlockChain& _bc, TransactionQueue&, OverlayDB& _o); + h256Set sync(BlockChain& _bc, TransactionQueue&, OverlayDB& _o, unsigned _max); /// Conduct I/O, polling, syncing, whatever. /// Ideally all time-consuming I/O is done in a background thread or otherwise asynchronously, but you get this call every 100ms or so anyway. diff --git a/libethereum/PeerSession.cpp b/libethereum/PeerSession.cpp index 4c403a897..239163e86 100644 --- a/libethereum/PeerSession.cpp +++ b/libethereum/PeerSession.cpp @@ -31,9 +31,9 @@ using namespace eth; #define clogS(X) eth::LogOutputStream(false) << "| " << std::setw(2) << m_socket.native_handle() << "] " -static const eth::uint c_maxHashes = 128; ///< Maximum number of hashes GetChain will ever send. -static const eth::uint c_maxBlocks = 32; ///< Maximum number of blocks Blocks will ever send. -static const eth::uint c_maxBlocksAsk = 32; ///< Maximum number of blocks we ask to receive in Blocks (when using GetChain). +static const eth::uint c_maxHashes = 4096; ///< Maximum number of hashes GetChain will ever send. +static const eth::uint c_maxBlocks = 2048; ///< Maximum number of blocks Blocks will ever send. +static const eth::uint c_maxBlocksAsk = 512; ///< Maximum number of blocks we ask to receive in Blocks (when using GetChain). PeerSession::PeerSession(PeerServer* _s, bi::tcp::socket _socket, uint _rNId, bi::address _peerAddress, unsigned short _peerPort): m_server(_s), @@ -111,24 +111,9 @@ bool PeerSession::interpret(RLP const& _r) m_server->m_peers[m_id] = shared_from_this(); - // Grab their block chain off them. + // Grab trsansactions off them. { - uint n = m_server->m_chain->number(m_server->m_latestBlockSent); - clogS(NetAllDetail) << "Want chain. Latest:" << m_server->m_latestBlockSent << ", number:" << n; - uint count = std::min(c_maxHashes, n + 1); RLPStream s; - prep(s).appendList(2 + count); - s << GetChainPacket; - auto h = m_server->m_latestBlockSent; - for (uint i = 0; i < count; ++i, h = m_server->m_chain->details(h).parent) - { - clogS(NetAllDetail) << " " << i << ":" << h; - s << h; - } - - s << c_maxBlocksAsk; - sealAndSend(s); - s.clear(); prep(s).appendList(1); s << GetTransactionsPacket; sealAndSend(s); @@ -240,16 +225,27 @@ bool PeerSession::interpret(RLP const& _r) } } m_rating += used; - if (g_logVerbosity >= 3) + unsigned knownParents = 0; + unsigned unknownParents = 0; + if (g_logVerbosity >= 2) + { for (unsigned i = 1; i < _r.itemCount(); ++i) { auto h = sha3(_r[i].data()); BlockInfo bi(_r[i].data()); if (!m_server->m_chain->details(bi.parentHash) && !m_knownBlocks.count(bi.parentHash)) + { + unknownParents++; clogS(NetMessageDetail) << "Unknown parent " << bi.parentHash << " of block " << h; + } else + { + knownParents++; clogS(NetMessageDetail) << "Known parent " << bi.parentHash << " of block " << h; + } } + } + clogS(NetMessageSummary) << dec << knownParents << " known parents, " << unknownParents << "unknown, " << used << "used."; if (used) // we received some - check if there's any more { RLPStream s; @@ -259,6 +255,8 @@ bool PeerSession::interpret(RLP const& _r) s << c_maxBlocksAsk; sealAndSend(s); } + else + clogS(NetMessageSummary) << "Peer sent all blocks in chain."; break; } case GetChainPacket: @@ -316,6 +314,9 @@ bool PeerSession::interpret(RLP const& _r) clogS(NetAllDetail) << " " << dec << i << " " << h; s.appendRaw(m_server->m_chain->block(h)); } + + if (!count) + clogS(NetMessageSummary) << "Sent peer all we have."; clogS(NetAllDetail) << "Parent: " << h; } else if (parent != parents.back()) @@ -487,7 +488,7 @@ void PeerSession::dropped() if (m_socket.is_open()) try { - clogS(NetNote) << "Closing " << m_socket.remote_endpoint(); + clogS(NetConnect) << "Closing " << m_socket.remote_endpoint(); m_socket.close(); } catch (...) {} @@ -503,7 +504,7 @@ void PeerSession::dropped() void PeerSession::disconnect(int _reason) { - clogS(NetNote) << "Disconnecting (reason:" << reasonOf((DisconnectReason)_reason) << ")"; + clogS(NetConnect) << "Disconnecting (reason:" << reasonOf((DisconnectReason)_reason) << ")"; if (m_socket.is_open()) { if (m_disconnect == chrono::steady_clock::time_point::max()) @@ -531,6 +532,25 @@ void PeerSession::start() doRead(); } +void PeerSession::startInitialSync() +{ + uint n = m_server->m_chain->number(m_server->m_latestBlockSent); + clogS(NetAllDetail) << "Want chain. Latest:" << m_server->m_latestBlockSent << ", number:" << n; + uint count = std::min(c_maxHashes, n + 1); + RLPStream s; + prep(s).appendList(2 + count); + s << GetChainPacket; + auto h = m_server->m_latestBlockSent; + for (uint i = 0; i < count; ++i, h = m_server->m_chain->details(h).parent) + { + clogS(NetAllDetail) << " " << i << ":" << h; + s << h; + } + + s << c_maxBlocksAsk; + sealAndSend(s); +} + void PeerSession::doRead() { // ignore packets received while waiting to disconnect diff --git a/libethereum/PeerSession.h b/libethereum/PeerSession.h index 1a28c66ec..6c7e56d7c 100644 --- a/libethereum/PeerSession.h +++ b/libethereum/PeerSession.h @@ -51,6 +51,8 @@ public: bi::tcp::endpoint endpoint() const; ///< for other peers to connect to. private: + void startInitialSync(); + void dropped(); void doRead(); void doWrite(std::size_t length); diff --git a/libqethereum/QEthereum.h b/libqethereum/QEthereum.h index 2707ba9ab..70a41c32d 100644 --- a/libqethereum/QEthereum.h +++ b/libqethereum/QEthereum.h @@ -187,7 +187,7 @@ private: frame->disconnect(); \ frame->addToJavaScriptWindowObject("env", env, QWebFrame::QtOwnership); \ frame->addToJavaScriptWindowObject("eth", eth, QWebFrame::ScriptOwnership); \ - frame->evaluateJavaScript("eth.makeWatch = function(a) { var ww = eth.newWatch(a); var ret = { w: ww }; ret.uninstall = function() { eth.killWatch(w); }; ret.changed = function(f) { eth.watchChanged.connect(function(nw) { env.note('check:' + nw + ' vs ' + ww); if (nw == ww) f() }); }; ret.transactions = function() { return JSON.parse(eth.watchTransactions(this.w)) }; return ret; }"); \ + frame->evaluateJavaScript("eth.makeWatch = function(a) { var ww = eth.newWatch(a); var ret = { w: ww }; ret.uninstall = function() { eth.killWatch(w); }; ret.changed = function(f) { eth.watchChanged.connect(function(nw) { if (nw == ww) f() }); }; ret.transactions = function() { return JSON.parse(eth.watchTransactions(this.w)) }; return ret; }"); \ frame->evaluateJavaScript("eth.watch = function(a) { return eth.makeWatch(JSON.stringify(a)) }"); \ frame->evaluateJavaScript("eth.watchChain = function() { return eth.makeWatch('chainChanged') }"); \ frame->evaluateJavaScript("eth.watchPending = function() { return eth.makeWatch('pendingChanged') }"); \