Logs in the remote captive-core server are unreadable

[2opremio]

The core logs in the captive-core remote http server wrapper are unreable (at least if there is an initialization error).

Many core lines are merged into a single line, making it extremely hard to read. I suspect it's a bug in the implementation of #3189

sweepey:horizon-captive-core fons$ kubectl logs deployments/horizon-with-remote-core  -f remote-core
time="2020-11-17T19:37:52.283Z" level=warning msg="Could not prepare range" error="opening subprocess: Error fast-forwarding to 335596: error reading frame length: unmarshalling XDR frame header: xdr:DecodeUint: EOF while decoding 4 bytes - read: '[]'" pid=1 preparedRange="[335596,latest)"
<startup> [default INFO] Config from /etc/stellar/stellar-core.cfg<startup> [default INFO] Generated QUORUM_SET: {"t" : 2,"v" : [ "sdf_testnet_2", "sdf_testnet_3", "sdf_testnet_1" ]}<startup> [default INFO] Assigning calculated value of 1 to FAILURE_SAFETYGB53O [default INFO] Starting stellar-core stellar-core 15.0.0 (8d6e6d74cfae65943211bdcc5ba083976d525a04)GB53O [Database INFO] Connecting to: sqlite3://:memory:GB53O [Ledger INFO] Streaming metadata to file descriptor 3GB53O [SCP INFO] LocalNode::LocalNode@GB53O qSet: 59d361GB53O [default INFO] Listening on 0.0.0.0:11626 for HTTP requestsGB53O [default INFO] *GB53O [default INFO] * The database has been initializedGB53O [default INFO] *GB53O [Database INFO] Applying DB schema upgrade to version 13GB53O [Database INFO] DB schema is in current versionGB53O [Ledger INFO] Established genesis ledger, closingGB53O [Ledger INFO] Root account seed: SDHOAMBNLGCE2MV5ZKIVZAQD3VCLGP53P3OBSBI6UN5L5XZI5TKHFQL4GB53O [History INFO] Archive 'sdf_testnet_1' has 'get' command only, will not be writtenGB53O [History INFO] Archive 'sdf_testnet_2' has 'get' command only, will not be writtenGB53O [History INFO] Archive 'sdf_testnet_3' has 'get' command only, will not be writtenGB53O [History WARNING] No writable archives configured, history will not be written.GB53O [Ledger INFO] Starting up applicationGB53O [default INFO] Connection effective settings:GB53O [default INFO] TARGET_PEER_CONNECTIONS: 8GB53O [default INFO] MAX_ADDITIONAL_PEER_CONNECTIONS: 64GB53O [default INFO] MAX_PENDING_CONNECTIONS: 500GB53O [default INFO] MAX_OUTBOUND_PENDING_CONNECTIONS: 56GB53O [default INFO] MAX_INBOUND_PENDING_CONNECTIONS: 444GB53O [Ledger INFO] Last closed ledger (LCL) hash is 63d98f536ee68d1b27b5b89f23af5311b7569a24faf1403ad0b52b633b07be99GB53O [Ledger INFO] LCL is genesis: [seq=1, hash=63d98f]GB53O [Ledger INFO] Assumed bucket-state for LCL: [seq=1, hash=63d98f]GB53O [Ledger INFO] Changing state LM_BOOTING_STATE -> LM_CATCHING_UP_STATEGB53O [History INFO] CatchupWork: selected archive sdf_testnet_3GB53O [History INFO] Starting catchup with configuration:lastClosedLedger: 1toLedger: 335550count: 0GB53O [History INFO] Catching up to ledger 335550: Downloading state file history/00/05/1e/history-00051ebf.json for ledger 335551GB53O [History INFO] Downloading history archive state: history/00/05/1e/history-00051ebf.jsonGB53O [History INFO] Catching up to ledger 335550: Downloading state file history/00/05/1e/history-00051e7f.json for ledger 335487GB53O [History INFO] Downloading history archive state: history/00/05/1e/history-00051e7f.jsonGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 1/2 (50%)GB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 2/2 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 2/2 children completedGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 4/4 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 4/4 children completedGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 6/6 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 6/6 children completedGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 8/8 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 8/8 children completedGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 10/10 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 10/10 children completedGB53O [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GB53O [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 12/12 children completedGB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGB53O [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GB53O [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GB53O [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GB53O [History INFO] Verifying ledgers [335487,335551)GB53O [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGB53O [History INFO] Catching up to ledger 335550: Failed: download-verify-ledgers-seqGB53O [History WARNING] Catchup failedGB53O [default INFO] *GB53O [default INFO] * Catchup failed.GB53O [default INFO] *GB53O [default INFO] Application destructingGB53O [default INFO] Application destroyed<startup> [default INFO] Config from /etc/stellar/stellar-core.cfg<startup> [default INFO] Generated QUORUM_SET: {"t" : 2,"v" : [ "sdf_testnet_2", "sdf_testnet_3", "sdf_testnet_1" ]}<startup> [default INFO] Assigning calculated value of 1 to FAILURE_SAFETYGDXIU [default INFO] Starting stellar-core stellar-core 15.0.0 (8d6e6d74cfae65943211bdcc5ba083976d525a04)GDXIU [Database INFO] Connecting to: sqlite3://:memory:GDXIU [Ledger INFO] Streaming metadata to file descriptor 3GDXIU [SCP INFO] LocalNode::LocalNode@GDXIU qSet: 59d361GDXIU [default INFO] Listening on 0.0.0.0:11626 for HTTP requestsGDXIU [default INFO] *GDXIU [default INFO] * The database has been initializedGDXIU [default INFO] *GDXIU [Database INFO] Applying DB schema upgrade to version 13GDXIU [Database INFO] DB schema is in current versionGDXIU [Ledger INFO] Established genesis ledger, closingGDXIU [Ledger INFO] Root account seed: SDHOAMBNLGCE2MV5ZKIVZAQD3VCLGP53P3OBSBI6UN5L5XZI5TKHFQL4GDXIU [History INFO] Archive 'sdf_testnet_1' has 'get' command only, will not be writtenGDXIU [History INFO] Archive 'sdf_testnet_2' has 'get' command only, will not be writtenGDXIU [History INFO] Archive 'sdf_testnet_3' has 'get' command only, will not be writtenGDXIU [History WARNING] No writable archives configured, history will not be written.GDXIU [Ledger INFO] Starting up applicationGDXIU [default INFO] Connection effective settings:GDXIU [default INFO] TARGET_PEER_CONNECTIONS: 8GDXIU [default INFO] MAX_ADDITIONAL_PEER_CONNECTIONS: 64GDXIU [default INFO] MAX_PENDING_CONNECTIONS: 500GDXIU [default INFO] MAX_OUTBOUND_PENDING_CONNECTIONS: 56GDXIU [default INFO] MAX_INBOUND_PENDING_CONNECTIONS: 444GDXIU [Ledger INFO] Last closed ledger (LCL) hash is 63d98f536ee68d1b27b5b89f23af5311b7569a24faf1403ad0b52b633b07be99GDXIU [Ledger INFO] LCL is genesis: [seq=1, hash=63d98f]GDXIU [Ledger INFO] Assumed bucket-state for LCL: [seq=1, hash=63d98f]GDXIU [Ledger INFO] Changing state LM_BOOTING_STATE -> LM_CATCHING_UP_STATEGDXIU [History INFO] CatchupWork: selected archive sdf_testnet_3GDXIU [History INFO] Starting catchup with configuration:lastClosedLedger: 1toLedger: 335550count: 0GDXIU [History INFO] Catching up to ledger 335550: Downloading state file history/00/05/1e/history-00051ebf.json for ledger 335551GDXIU [History INFO] Downloading history archive state: history/00/05/1e/history-00051ebf.jsonGDXIU [History INFO] Catching up to ledger 335550: Downloading state file history/00/05/1e/history-00051e7f.json for ledger 335487GDXIU [History INFO] Downloading history archive state: history/00/05/1e/history-00051e7f.jsonGDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 1/2 (50%)GDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 2/2 children completedGDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGDXIU [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GDXIU [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GDXIU [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 2/2 children completedGDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 4/4 children completedGDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGDXIU [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GDXIU [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GDXIU [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 4/4 children completedGDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 6/6 children completedGDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGDXIU [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GDXIU [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GDXIU [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 6/6 children completedGDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 8/8 children completedGDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Verifying ledger [seq=335550, hash=2341eb] against SCP hashGDXIU [History ERROR] Checkpoint does not agree with checkpoint ahead: current [seq=335550, hash=2341eb], verified: [seq=335550, hash=4f71a5] [VerifyLedgerChainWork.cpp:336]GDXIU [History ERROR] Catchup material failed verification - hash mismatch, propagating failure [VerifyLedgerChainWork.cpp:443]GDXIU [History ERROR] One or more of history archives may be corrupted. Update HISTORY configuration entry to only contain valid ones [VerifyLedgerChainWork.cpp:445]GDXIU [History INFO] Verifying ledgers [335487,335551)GDXIU [History INFO] Catching up to ledger 335550: Failed: verify-ledger-chainGDXIU [History INFO] Catching up to ledger 335550: Succeeded: batch-download-ledger-00051e7f-00051eff : 8/8 children completedGDXIU [History INFO] Catching up to ledger 335550: downloading ledger files 2/2 (100%)GDXIU [History INFO] Catching up to ledger 335550: Succeeded: batctime="2020-11-17T19:38:06.832Z" level=warning msg="Could not prepare range" error="opening subprocess: Error fast-forwarding to 335596: error reading frame length: unmarshalling XDR frame header: xdr:DecodeUint: EOF while decoding 4 bytes - read: '[]'" pid=1 preparedRange="[335596,latest)"

[Shaptic]

Can you provide a little more context on the configuration? I followed these deployment instructions and I get this for the same command:

$ kubectl logs deployment/horizon-with-remote-core -f remote-core | head -n 8
<startup> [default INFO] Config from /etc/stellar/stellar-core.cfg
<startup> [default INFO] Generated QUORUM_SET: {
   "t" : 2,
   "v" : [ "sdf_testnet_2", "sdf_testnet_3", "sdf_testnet_1" ]
}

<startup> [default INFO] Assigning calculated value of 1 to FAILURE_SAFETY
GANKR [default INFO] Starting stellar-core stellar-core 15.0.0 (8d6e6d74cfae65943211bdcc5ba083976d525a04)
...

One thing that stands out is the fact that it doesn't seem like I have the Go-formatted Horizon logs at all; these appear to be pure Core logs. How can I cause/force an initialization error?