Skip to content

mlog API

Jump to bottom
ia edited this page Aug 25, 2017 · 27 revisions

mlog API

  • Note: this feature is forthcoming, and hasn't yet been included in a release.

Quick links

Overview

mlog stands for "machine logging." To read the spec for mlog implementation and documenation, please visit the mlog spec page.

mlog has the following option flags:

  • --mlog (default:kv): specifies format in which mlog lines should be structured; possible format values are kv (key-value), json, and plain (same as key-value, but with just values), as well as off to disable mlog entirely
  • --mlog-dir (default: <datadir>/<chain-identity>/mlogs): directory to hold mlogs
  • --mlog-components (default: all available): comma-separated list of components which should be logged. For a list of available components, please see the lines reference section.

Machine logging is enabled by default. To disable it, use --mlog=off.

Directory and files

Machine log files are automatically generated in the /mlogs subdirectory of the chain data directory of the running geth instance, for example:

$HOME/Library/EthereumClassic/mainnet/mlogs/

To customize this location, use --mlog-dir=/path/to/mlogs, where /path/to/mlogs may be an absolute or relative path to a directory. This directory will be created if it doesn't exist.

Machine log file names include context and time information. The latest mlog file will be symlinked as <programname>.log. For example:

lrwxr-xr-x 1 ia staff   37 Aug  1 13:49 geth.log -> geth.mh.ia.mlog.20170801-134958.33641
-rw-r--r-- 1 ia staff    0 Aug  1 13:45 geth.mh.ia.mlog.20170801-134515.32147
-rw-r--r-- 1 ia staff 6.0K Aug  1 13:49 geth.mh.ia.mlog.20170801-134853.33260
-rw-r--r-- 1 ia staff 3.8K Aug  1 13:49 geth.mh.ia.mlog.20170801-134946.33525
-rw-r--r-- 1 ia staff    0 Aug  1 13:49 geth.mh.ia.mlog.20170801-134958.33641

A new mlog file is generated each time a geth node is run.

Line structure

A line is the result of a single event in the go-ethereum protocol.

There are three available formats:

  • Key-value (aka kv): default
  • Plain
  • JSON

Key-value & Plain

Lines are organized with a common structure:

$DATE $TIME [$cmp] RECEIVER VERB SUBJECT $RECEIVER:DETAIL $RECEIVER:DETAIL $SUBJECT:DETAIL $SUBJECT:DETAIL

where the number and types of details vary for different lines.

For example:

2017-08-24T17:17:39Z [discover] PING HANDLE FROM from.udp_address=123.45.67.89:30303 from.id=7909d51011d8a153 ping.bytes_transferred=252

Note: In this documentation, line variable names which represent dynamic values (eg. $STRING) are prefixed with $, while constant values (eg. SEND) are not prefixed.

Line structure can be understood in three parts:

Header: 2017-08-24T17:17:39Z [discover]

The first value is the date in UTC ISO8601 format; %Y-%m-%dT%H:%M:%SZ.

The second value is the trace component calling the log. The component name will always be in brackets. Header structure is the same for all kv and plain lines, but is excluded from json-formatted lines.

Fingerprint: PING HANDLE FROM

lines are referred to and organized by their unique fingerprint pattern: RECEIVER VERB SUBJECT. For json-formatted lines, this pattern will be present within the logged json objects as "event": "receiver.subject.verb".

Details: 123.45.67.89:30303 7909d51011d8a153 252

All DETAIL values that may contain spaces are wrapped in quotes, eg. disconnect.reason="Disconnect requested".

If formatting is set to key-value, DETAILS will include owner.key=$SOMEVALUE, eg:

from.udp_address=123.45.67.89:30303 from.id=7909d51011d8a153 ping.bytes_transferred=252

An example configuration for parsing key-value logs using Filebeat with an ELK (Elasticsearch, Logstash, Kibana) stack might look something like this:

# filebeath.geth.mlog.json
filebeat.prospectors:
- input_type: log
  paths:
  # can also use wildcards, eg. *.log
    - /Users/ia/Library/EthereumClassic/mlogs/geth.log
  symlinks: true
output.logstash:
  hosts: ["localhost:5043"]
# logstash-kv.conf
input {
    beats {
        port => "5043"
    }
}
# The filter part of this file is commented out to indicate that it is
# optional.
filter {
    date {
        match => [ "logdate", "yyyy-MM-ddTHH:mm:ssZ"]
    }
    grok {
        match => { "message" => "\[%{WORD:component}\] %{WORD:receiver} %{WORD:verb} %{WORD:subject}" }
    }
    mutate {
        convert => {
            "SERVER.PEER_COUNT" => "integer"
        }
    }
}
output {
    stdout { }
    elasticsearch {
        hosts => "localhost:9200"
    }
}

JSON

Each line logged in JSON format contains a single JSON object, and is not prefixed by a timestamp or component prefix. For example:

{"event":"state.create.object","object.new":"string","object.prev":"string","ts":"2017-08-24T13:49:03.787138646-05:00"}

Additional keys

Each JSON-formatted line contains two additional keys:

  • "event": the 'fingerprint' of the line event. This, for example, may be used as the json.event_key value for Logstash.
  • "ts": the timestamp of the event. Note that this is the time at which the event was logged, not the time at which the line may be ingested by a log parsing program. The value will be in the form 2017-08-10T15:20:11.294317237-05:00.

Flatness

The JSON line details should be as "flat" as possible; instead of presenting:

{"node": {"ip": "1234asdf", "port": 3333}}

the line will prefer a format like:

{"node.ip": "1234asdf", "node.port": 3333}

An example configuration for parsing JSON logs using Filebeat with an ELK (Elasticsearch, Logstash, Kibana) stack might look something like this:

# filebeat.geth.mlog.json.yml
filebeat.prospectors:
- input_type: log
  paths:
    - /Users/ia/Library/EthereumClassic/mlogs/geth.log
  symlinks: true
  json.message_key: event
  json.keys_under_root: true
output.logstash:
  hosts: ["localhost:5043"]
# logstash-json.conf
input {
    beats {
        port => "5043"
    }
}
output {
    stdout { }
    elasticsearch {
        hosts => "localhost:9200"
    }
}

Lines reference

Component Description
discover The discover component handles low-level peer discovery requests.
blockchain The blockchain component tracks block and chain insertions into the chaindb during import and sync.
server The server component tracks peer-to-peer registrations.
miner The miner component tracks mining actions, including uncle and transaction commits.
state The state component tracks address creation and balance changes.
txpool The txpool component tracks the addition and validation of transactions.

[discover]

[state]

[blockchain]

[txpool]

[miner]

[server]

STATE CREATE OBJECT

Called once when a state object is created. $OBJECT.NEW is the address of the newly-created object. If there was an existing account with the same address, it is overwritten and its address returned as the $OBJECT.PREV value.

Key value:

2017/08/24 13:49:03 [state] STATE CREATE OBJECT object.new=$STRING object.prev=$STRING

JSON:

{"event":"state.create.object","object.new":"string","object.prev":"string","ts":"2017-08-24T13:49:03.787138646-05:00"}

Plain:

2017/08/24 13:49:03 [state] STATE CREATE OBJECT $STRING $STRING

2 detail values:

  • object.new: $STRING
  • object.prev: $STRING

STATE ADD_BALANCE OBJECT

Called once when the balance of an account (state object) is added to.

Key value:

2017/08/24 13:49:03 [state] STATE ADD_BALANCE OBJECT object.address=$STRING object.nonce=$INT object.balance=$BIGINT add_balance.amount=$BIGINT

JSON:

{"add_balance.amount":0,"event":"state.add_balance.object","object.address":"string","object.balance":0,"object.nonce":0,"ts":"2017-08-24T13:49:03.787592656-05:00"}

Plain:

2017/08/24 13:49:03 [state] STATE ADD_BALANCE OBJECT $STRING $INT $BIGINT $BIGINT

4 detail values:

  • object.address: $STRING
  • object.nonce: $INT
  • object.balance: $BIGINT
  • add_balance.amount: $BIGINT

STATE SUB_BALANCE OBJECT

Called once when the balance of an account (state object) is subtracted from.

Key value:

2017/08/24 13:49:03 [state] STATE SUB_BALANCE OBJECT object.address=$STRING object.nonce=$INT object.balance=$BIGINT sub_balance.amount=$BIGINT

JSON:

{"event":"state.sub_balance.object","object.address":"string","object.balance":0,"object.nonce":0,"sub_balance.amount":0,"ts":"2017-08-24T13:49:03.787736283-05:00"}

Plain:

2017/08/24 13:49:03 [state] STATE SUB_BALANCE OBJECT $STRING $INT $BIGINT $BIGINT

4 detail values:

  • object.address: $STRING
  • object.nonce: $INT
  • object.balance: $BIGINT
  • sub_balance.amount: $BIGINT

BLOCKCHAIN WRITE BLOCK

Called when a single block written to the chain database. A STATUS of NONE means it was written without any abnormal chain event, such as a split.

Key value:

2017/08/24 13:49:03 [blockchain] BLOCKCHAIN WRITE BLOCK write.status=$STRING write.error=$STRING_OR_NULL block.number=$BIGINT block.hash=$STRING block.size=$INT64 block.transactions_count=$INT block.gas_used=$BIGINT block.coinbase=$STRING block.time=$BIGINT

JSON:

{"block.coinbase":"string","block.gas_used":0,"block.hash":"string","block.number":0,"block.size":null,"block.time":0,"block.transactions_count":0,"event":"blockchain.write.block","ts":"2017-08-24T13:49:03.787808456-05:00","write.error":null,"write.status":"string"}

Plain:

2017/08/24 13:49:03 [blockchain] BLOCKCHAIN WRITE BLOCK $STRING $STRING_OR_NULL $BIGINT $STRING $INT64 $INT $BIGINT $STRING $BIGINT

9 detail values:

  • write.status: $STRING
  • write.error: $STRING_OR_NULL
  • block.number: $BIGINT
  • block.hash: $STRING
  • block.size: $INT64
  • block.transactions_count: $INT
  • block.gas_used: $BIGINT
  • block.coinbase: $STRING
  • block.time: $BIGINT

BLOCKCHAIN INSERT BLOCKS

Called when a chain of blocks is inserted into the chain database.

Key value:

2017/08/24 13:49:03 [blockchain] BLOCKCHAIN INSERT BLOCKS blocks.count=$INT blocks.queued=$INT blocks.ignored=$INT blocks.transactions_count=$INT blocks.last_number=$BIGINT blocks.first_hash=$STRING blocks.last_hash=$STRING insert.time=$DURATION

JSON:

{"blocks.count":0,"blocks.first_hash":"string","blocks.ignored":0,"blocks.last_hash":"string","blocks.last_number":0,"blocks.queued":0,"blocks.transactions_count":0,"event":"blockchain.insert.blocks","insert.time":63042000000,"ts":"2017-08-24T13:49:03.787961799-05:00"}

Plain:

2017/08/24 13:49:03 [blockchain] BLOCKCHAIN INSERT BLOCKS $INT $INT $INT $INT $BIGINT $STRING $STRING $DURATION

8 detail values:

  • blocks.count: $INT
  • blocks.queued: $INT
  • blocks.ignored: $INT
  • blocks.transactions_count: $INT
  • blocks.last_number: $BIGINT
  • blocks.first_hash: $STRING
  • blocks.last_hash: $STRING
  • insert.time: $DURATION

TXPOOL ADD TX

Called once when a valid transaction is added to tx pool. $TO.NAME will be the account address hex or '[NEW_CONTRACT]' in case of a contract.

Key value:

2017/08/24 13:49:03 [txpool] TXPOOL ADD TX tx.from=$STRING tx.to=$STRING tx.value=$BIGINT tx.hash=$STRING

JSON:

{"event":"txpool.add.tx","ts":"2017-08-24T13:49:03.788067157-05:00","tx.from":"string","tx.hash":"string","tx.to":"string","tx.value":0}

Plain:

2017/08/24 13:49:03 [txpool] TXPOOL ADD TX $STRING $STRING $BIGINT $STRING

4 detail values:

  • tx.from: $STRING
  • tx.to: $STRING
  • tx.value: $BIGINT
  • tx.hash: $STRING

TXPOOL VALIDATE TX

Called once when validating a single transaction. If transaction is invalid, TX.ERROR will be non-nil, otherwise it will be nil.

Key value:

2017/08/24 13:49:03 [txpool] TXPOOL VALIDATE TX tx.hash=$STRING tx.error=$STRING_OR_NULL

JSON:

{"event":"txpool.validate.tx","ts":"2017-08-24T13:49:03.788142391-05:00","tx.error":null,"tx.hash":"string"}

Plain:

2017/08/24 13:49:03 [txpool] TXPOOL VALIDATE TX $STRING $STRING_OR_NULL

2 detail values:

  • tx.hash: $STRING
  • tx.error: $STRING_OR_NULL

MINER START COINBASE

Called once when the miner starts.

Key value:

2017/08/24 13:49:03 [miner] MINER START COINBASE coinbase.address=$STRING miner.threads=$INT

JSON:

{"coinbase.address":"string","event":"miner.start.coinbase","miner.threads":0,"ts":"2017-08-24T13:49:03.788187545-05:00"}

Plain:

2017/08/24 13:49:03 [miner] MINER START COINBASE $STRING $INT

2 detail values:

  • coinbase.address: $STRING
  • miner.threads: $INT

MINER STOP COINBASE

Called once when the miner stops.

Key value:

2017/08/24 13:49:03 [miner] MINER STOP COINBASE coinbase.address=$STRING miner.threads=$INT

JSON:

{"coinbase.address":"string","event":"miner.stop.coinbase","miner.threads":0,"ts":"2017-08-24T13:49:03.788228452-05:00"}

Plain:

2017/08/24 13:49:03 [miner] MINER STOP COINBASE $STRING $INT

2 detail values:

  • coinbase.address: $STRING
  • miner.threads: $INT

MINER COMMIT_WORK BLOCK

Called when the miner commits new work on a block.

Key value:

2017/08/24 13:49:03 [miner] MINER COMMIT_WORK BLOCK block.number=$BIGINT commit_work.txs_count=$INT commit_work.uncles_count=$INT commit_work.time_elapsed=$DURATION

JSON:

{"block.number":0,"commit_work.time_elapsed":63042000000,"commit_work.txs_count":0,"commit_work.uncles_count":0,"event":"miner.commit_work.block","ts":"2017-08-24T13:49:03.788285866-05:00"}

Plain:

2017/08/24 13:49:03 [miner] MINER COMMIT_WORK BLOCK $BIGINT $INT $INT $DURATION

4 detail values:

  • block.number: $BIGINT
  • commit_work.txs_count: $INT
  • commit_work.uncles_count: $INT
  • commit_work.time_elapsed: $DURATION

MINER COMMIT UNCLE

Called when the miner commits an uncle. If $COMMIT_UNCLE is non-nil, uncle is not committed.

Key value:

2017/08/24 13:49:03 [miner] MINER COMMIT UNCLE commit.block_number=$BIGINT uncle.hash=$STRING commit.error=$STRING_OR_NULL

JSON:

{"commit.block_number":0,"commit.error":null,"event":"miner.commit.uncle","ts":"2017-08-24T13:49:03.788348731-05:00","uncle.hash":"string"}

Plain:

2017/08/24 13:49:03 [miner] MINER COMMIT UNCLE $BIGINT $STRING $STRING_OR_NULL

3 detail values:

  • commit.block_number: $BIGINT
  • uncle.hash: $STRING
  • commit.error: $STRING_OR_NULL

MINER COMMIT TX

Called when the miner commits (or attempts to commit) a transaction. If $COMMIT.ERROR is non-nil, the transaction is not committed.

Key value:

2017/08/24 13:49:03 [miner] MINER COMMIT TX commit.block_number=$BIGINT tx.hash=$STRING commit.error=$STRING

JSON:

{"commit.block_number":0,"commit.error":"string","event":"miner.commit.tx","ts":"2017-08-24T13:49:03.788387403-05:00","tx.hash":"string"}

Plain:

2017/08/24 13:49:03 [miner] MINER COMMIT TX $BIGINT $STRING $STRING

3 detail values:

  • commit.block_number: $BIGINT
  • tx.hash: $STRING
  • commit.error: $STRING

MINER MINE BLOCK

Called when the miner has mined a block. $BLOCK.STATUS will be either 'stale' or 'wait_confirm'. $BLOCK.WAIT_CONFIRM is an integer specifying n blocks to wait for confirmation based on block depth, relevant only for when $BLOCK.STATUS is 'wait_confirm'.

Key value:

2017/08/24 13:49:03 [miner] MINER MINE BLOCK block.number=$BIGINT block.hash=$STRING block.status=$STRING block.wait_confirm=$INT

JSON:

{"block.hash":"string","block.number":0,"block.status":"string","block.wait_confirm":0,"event":"miner.mine.block","ts":"2017-08-24T13:49:03.788436062-05:00"}

Plain:

2017/08/24 13:49:03 [miner] MINER MINE BLOCK $BIGINT $STRING $STRING $INT

4 detail values:

  • block.number: $BIGINT
  • block.hash: $STRING
  • block.status: $STRING
  • block.wait_confirm: $INT

MINER CONFIRM_MINED BLOCK

Called once to confirm the miner has mined a block n blocks back, where n refers to the $BLOCK.WAIT_CONFIRM value from MINER MINE BLOCK. This is only a logging confirmation message, and is not related to work done.

Key value:

2017/08/24 13:49:03 [miner] MINER CONFIRM_MINED BLOCK block.number=$INT

JSON:

{"block.number":0,"event":"miner.confirm_mined.block","ts":"2017-08-24T13:49:03.788484285-05:00"}

Plain:

2017/08/24 13:49:03 [miner] MINER CONFIRM_MINED BLOCK $INT

1 detail values:

  • block.number: $INT

SERVER ADD PEER

Called once when a peer is added.

Key value:

2017/08/24 13:49:03 [server] SERVER ADD PEER server.peer_count=$INT peer.id=$STRING peer.remote_addr=$STRING peer.remote_version=$STRING

JSON:

{"event":"server.add.peer","peer.id":"string","peer.remote_addr":"string","peer.remote_version":"string","server.peer_count":0,"ts":"2017-08-24T13:49:03.788512046-05:00"}

Plain:

2017/08/24 13:49:03 [server] SERVER ADD PEER $INT $STRING $STRING $STRING

4 detail values:

  • server.peer_count: $INT
  • peer.id: $STRING
  • peer.remote_addr: $STRING
  • peer.remote_version: $STRING

SERVER REMOVE PEER

Called once when a peer is removed.

Key value:

2017/08/24 13:49:03 [server] SERVER REMOVE PEER server.peer_count=$INT peer.id=$STRING remove.reason=$QUOTEDSTRING

JSON:

{"event":"server.remove.peer","peer.id":"string","remove.reason":"string with spaces","server.peer_count":0,"ts":"2017-08-24T13:49:03.788561644-05:00"}

Plain:

2017/08/24 13:49:03 [server] SERVER REMOVE PEER $INT $STRING $QUOTEDSTRING

3 detail values:

  • server.peer_count: $INT
  • peer.id: $STRING
  • remove.reason: $QUOTEDSTRING

PING HANDLE FROM

Called once for each received PING request from peer FROM.

Key value:

2017/08/24 13:49:03 [discover] PING HANDLE FROM from.udp_address=$STRING from.id=$STRING ping.bytes_transferred=$INT

JSON:

{"event":"ping.handle.from","from.id":"string","from.udp_address":"string","ping.bytes_transferred":0,"ts":"2017-08-24T13:49:03.788618848-05:00"}

Plain:

2017/08/24 13:49:03 [discover] PING HANDLE FROM $STRING $STRING $INT

3 detail values:

  • from.udp_address: $STRING
  • from.id: $STRING
  • ping.bytes_transferred: $INT

PING SEND TO

Called once for each outgoing PING request to peer TO.

Key value:

2017/08/24 13:49:03 [discover] PING SEND TO to.udp_address=$STRING ping.bytes_transferred=$INT

JSON:

{"event":"ping.send.to","ping.bytes_transferred":0,"to.udp_address":"string","ts":"2017-08-24T13:49:03.788663795-05:00"}

Plain:

2017/08/24 13:49:03 [discover] PING SEND TO $STRING $INT

2 detail values:

  • to.udp_address: $STRING
  • ping.bytes_transferred: $INT

PONG HANDLE FROM

Called once for each received PONG request from peer FROM.

Key value:

2017/08/24 13:49:03 [discover] PONG HANDLE FROM from.udp_address=$STRING from.id=$STRING pong.bytes_transferred=$INT

JSON:

{"event":"pong.handle.from","from.id":"string","from.udp_address":"string","pong.bytes_transferred":0,"ts":"2017-08-24T13:49:03.788702648-05:00"}

Plain:

2017/08/24 13:49:03 [discover] PONG HANDLE FROM $STRING $STRING $INT

3 detail values:

  • from.udp_address: $STRING
  • from.id: $STRING
  • pong.bytes_transferred: $INT

PONG SEND TO

Called once for each outgoing PONG request to peer TO.

Key value:

2017/08/24 13:49:03 [discover] PONG SEND TO to.udp_address=$STRING pong.bytes_transferred=$INT

JSON:

{"event":"pong.send.to","pong.bytes_transferred":0,"to.udp_address":"string","ts":"2017-08-24T13:49:03.788744248-05:00"}

Plain:

2017/08/24 13:49:03 [discover] PONG SEND TO $STRING $INT

2 detail values:

  • to.udp_address: $STRING
  • pong.bytes_transferred: $INT

FINDNODE HANDLE FROM

Called once for each received FIND_NODE request from peer FROM.

Key value:

2017/08/24 13:49:03 [discover] FINDNODE HANDLE FROM from.udp_address=$STRING from.id=$STRING findnode.bytes_transferred=$INT

JSON:

{"event":"findnode.handle.from","findnode.bytes_transferred":0,"from.id":"string","from.udp_address":"string","ts":"2017-08-24T13:49:03.788776447-05:00"}

Plain:

2017/08/24 13:49:03 [discover] FINDNODE HANDLE FROM $STRING $STRING $INT

3 detail values:

  • from.udp_address: $STRING
  • from.id: $STRING
  • findnode.bytes_transferred: $INT

FINDNODE SEND TO

Called once for each received FIND_NODE request from peer FROM.

Key value:

2017/08/24 13:49:03 [discover] FINDNODE SEND TO to.udp_address=$STRING findnode.bytes_transferred=$INT

JSON:

{"event":"findnode.send.to","findnode.bytes_transferred":0,"to.udp_address":"string","ts":"2017-08-24T13:49:03.788825171-05:00"}

Plain:

2017/08/24 13:49:03 [discover] FINDNODE SEND TO $STRING $INT

2 detail values:

  • to.udp_address: $STRING
  • findnode.bytes_transferred: $INT

NEIGHBORS HANDLE FROM

Called once for each received NEIGHBORS request from peer FROM.

Key value:

2017/08/24 13:49:03 [discover] NEIGHBORS HANDLE FROM from.udp_address=$STRING from.id=$STRING neighbors.bytes_transferred=$INT

JSON:

{"event":"neighbors.handle.from","from.id":"string","from.udp_address":"string","neighbors.bytes_transferred":0,"ts":"2017-08-24T13:49:03.788871852-05:00"}

Plain:

2017/08/24 13:49:03 [discover] NEIGHBORS HANDLE FROM $STRING $STRING $INT

3 detail values:

  • from.udp_address: $STRING
  • from.id: $STRING
  • neighbors.bytes_transferred: $INT

NEIGHBORS SEND TO

Called once for each outgoing NEIGHBORS request to peer TO.

Key value:

2017/08/24 13:49:03 [discover] NEIGHBORS SEND TO to.udp_address=$STRING neighbors.bytes_transferred=$INT

JSON:

{"event":"neighbors.send.to","neighbors.bytes_transferred":0,"to.udp_address":"string","ts":"2017-08-24T13:49:03.788920929-05:00"}

Plain:

2017/08/24 13:49:03 [discover] NEIGHBORS SEND TO $STRING $INT

2 detail values:

  • to.udp_address: $STRING
  • neighbors.bytes_transferred: $INT

❤️ Stay Classy

W Home

🔭 Webchain Project Wiki

Native DApps w/ Go

Reference

CLI Commands & Options

Connecting to the network

Managing Accounts

Mining

Sending WEB Tutorial

Indexing Accounts

Backup And Restore

JSON-RPC

JavaScript Console

Peer-to-Peer

Metrics and Monitoring

Releases Page

Contracts and Transactions

Contract Tutorial

Private Networking Tutorial

Native DApps in Go

FAQ

Discord Channel

Clone this wiki locally