Closed NiklasKunkel closed 4 years ago
This sounds like a serious bug, but before we can say that for sure, can you give us some context?
No I was using the only account exclusively on a single device. The database is about 5GB big.
Just had the same thing happen on a separate instance.
WARNING-DEPRECATION: `sbot server` has been renamed to `ssb-server start`
ssb-server 15.0.2 /home/nkunkel/.ssb logging.level:notice
my key ID: aS9pDFHSTfy2CY0PsO0hIpnY1BYgcpdGL2YWXHc73lI=.ed25519
ssb-friends: stream legacy api used
server error, from net:122.228.19.79:42608~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
server error, from net:122.228.19.79:42607~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
server error, from net:41.216.186.87:1184~shs:
Error: stream ended with:47 but wanted:64
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:43:26)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:63:18
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:147:5)
at Socket.emit (events.js:203:15)
at TCP._handle.close (net.js:606:12)
server error, from net:159.203.199.154:45582~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
server error, from net:178.32.129.16:62053~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
server error, from net:54.215.179.48:55880~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
internal/buffer.js:35
throw new ERR_OUT_OF_RANGE('value', `>= ${min} and <= ${max}`, value);
^
RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 4294967295. Received 4294967775
at checkInt (internal/buffer.js:35:11)
at writeU_Int32BE (internal/buffer.js:619:3)
at Buffer.writeUInt32BE (internal/buffer.js:632:10)
at Object.encode (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/offset-codecs.js:9:11)
at Object.frame (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/recoverable.js:23:19)
at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:19:26
at Function.many.once (/home/nkunkel/ssb-server/node_modules/obv/index.js:39:7)
at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:15:11
at drain (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:20:5)
at Object.write [as append] (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:30:41)```
Just happened to a third node.
WARNING-DEPRECATION: `sbot server` has been renamed to `ssb-server start`
ssb-server 15.0.2 /home/nkunkel/.ssb logging.level:notice
my key ID: 4wuvO7zjo4Cp71w1mUJBOXbRAZjtr91rt7bpfhcEDmE=.ed25519
ssb-friends: stream legacy api used
server error, from net:198.108.67.48:12518~shs:
Error: shs.server: client sent invalid challenge (phase 1), possibly they tried to speak a different protocol or had wrong application cap
at Object.cb (/home/nkunkel/ssb-server/node_modules/secret-handshake/protocol.js:88:30)
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:39:14)
at more (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:55:13)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:66:9
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:135:5)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:288:12)
at readableAddChunk (_stream_readable.js:269:11)
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760445]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760447]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760463]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760484]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760485]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760487]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
could not retrive msg: NotFoundError: Key not found in database [@EbPRv+q8uPZBd9C+ATINR7gRKgRC4eNz3a0NGMoneak=.ed25519,760527]
at /home/nkunkel/ssb-server/node_modules/levelup/lib/levelup.js:160:15
at /home/nkunkel/ssb-server/node_modules/encoding-down/index.js:50:21
Error: stream ended with:47 but wanted:64
at drain (/home/nkunkel/ssb-server/node_modules/pull-reader/index.js:43:26)
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:63:18
at /home/nkunkel/ssb-server/node_modules/pull-reader/index.js:20:7
at drain (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:126:18)
at Socket.<anonymous> (/home/nkunkel/ssb-server/node_modules/stream-to-pull-stream/index.js:147:5)
at Socket.emit (events.js:203:15)
at TCP._handle.close (net.js:606:12)
internal/buffer.js:35
throw new ERR_OUT_OF_RANGE('value', `>= ${min} and <= ${max}`, value);
^
RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 4294967295. Received 4294968097
at checkInt (internal/buffer.js:35:11)
at writeU_Int32BE (internal/buffer.js:619:3)
at Buffer.writeUInt32BE (internal/buffer.js:632:10)
at Object.encode (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/offset-codecs.js:9:11)
at Object.frame (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/recoverable.js:23:19)
at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:19:26
at Function.many.once (/home/nkunkel/ssb-server/node_modules/obv/index.js:39:7)
at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:15:11
at drain (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:20:5)
at Object.write [as append] (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:30:41)```
4th node just had the server crash with the same error.
WARNING-DEPRECATION:
sbot serverhas been renamed to
ssb-server start ssb-server 15.0.2 /home/nkunkel/.ssb logging.level:notice my key ID: lplSEbzl8cEDE7HTLQ2Fk2TasjZhEXbEzGzKBFQvVvc=.ed25519 ssb-friends: stream legacy api used Error replicating with @SoGPH4un5Voz98oAZIbo4hYftc4slv4A+OHXPGCFHpA=.ed25519: Error: parent stream is closing at PacketStream.stream (/home/nkunkel/ssb-server/node_modules/packet-stream/index.js:46:28) at Object.ws.remoteCall (/home/nkunkel/ssb-server/node_modules/muxrpc/stream.js:116:17) at /home/nkunkel/ssb-server/node_modules/muxrpc/index.js:46:15 at remoteCall (/home/nkunkel/ssb-server/node_modules/muxrpc/api.js:40:19) at EventEmitter.obj.(anonymous function) [as createHistoryStream] (/home/nkunkel/ssb-server/node_modules/muxrpc/api.js:25:18) at replicate (/home/nkunkel/ssb-server/node_modules/ssb-replicate/legacy.js:291:13) at EventEmitter.fallback (/home/nkunkel/ssb-server/node_modules/ssb-replicate/legacy.js:351:7) at Object.onceWrapper (events.js:286:20) at EventEmitter.emit (events.js:198:13) at /home/nkunkel/ssb-server/node_modules/ssb-ebt/index.js:144:15 Trace: deprecated api used: ssb-ref.parseAddress at Object.parseAddress (/home/nkunkel/ssb-server/node_modules/ssb-ref/index.js:96:15) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/ssb-invite/index.js:212:24) at apply (/home/nkunkel/ssb-server/node_modules/muxrpc-validation/index.js:197:15) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/muxrpc-validation/index.js:86:14) at Object.hooked (/home/nkunkel/ssb-server/node_modules/hoox/index.js:10:15) at Object.localCall (/home/nkunkel/ssb-server/node_modules/muxrpc/local-api.js:31:29) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/muxrpc/local-api.js:37:22) at Object.request (/home/nkunkel/ssb-server/node_modules/muxrpc/stream.js:48:17) at PacketStream._onrequest (/home/nkunkel/ssb-server/node_modules/packet-stream/index.js:161:17) at PacketStream.write (/home/nkunkel/ssb-server/node_modules/packet-stream/index.js:134:41) Trace: deprecated api used: ssb-ref.parseInvite at Object.parseInvite (/home/nkunkel/ssb-server/node_modules/ssb-ref/index.js:96:15) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/ssb-invite/index.js:223:37) at apply (/home/nkunkel/ssb-server/node_modules/muxrpc-validation/index.js:197:15) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/muxrpc-validation/index.js:86:14) at Object.hooked (/home/nkunkel/ssb-server/node_modules/hoox/index.js:10:15) at Object.localCall (/home/nkunkel/ssb-server/node_modules/muxrpc/local-api.js:31:29) at Object.<anonymous> (/home/nkunkel/ssb-server/node_modules/muxrpc/local-api.js:37:22) at Object.request (/home/nkunkel/ssb-server/node_modules/muxrpc/stream.js:48:17) at PacketStream._onrequest (/home/nkunkel/ssb-server/node_modules/packet-stream/index.js:161:17) at PacketStream.write (/home/nkunkel/ssb-server/node_modules/packet-stream/index.js:134:41) internal/buffer.js:35 throw new ERR_OUT_OF_RANGE('value',
>= ${min} and <= ${max}, value); ^ RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 4294967295. Received 4294967589 at checkInt (internal/buffer.js:35:11) at writeU_Int32BE (internal/buffer.js:619:3) at Buffer.writeUInt32BE (internal/buffer.js:632:10) at Object.encode (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/offset-codecs.js:9:11) at Object.frame (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/recoverable.js:23:19) at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:19:26 at Function.many.once (/home/nkunkel/ssb-server/node_modules/obv/index.js:39:7) at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:15:11 at drain (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:20:5) at Object.write [as append] (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:30:41)
internal/buffer.js:35 throw new ERR_OUT_OF_RANGE('value',
>= ${min} and <= ${max}
, value); ^RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 4294967295. Received 4294967589 at checkInt (internal/buffer.js:35:11) at writeU_Int32BE (internal/buffer.js:619:3) at Buffer.writeUInt32BE (internal/buffer.js:632:10) at Object.encode (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/offset-codecs.js:9:11) at Object.frame (/home/nkunkel/ssb-server/node_modules/flumelog-offset/frame/recoverable.js:23:19) at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:19:26 at Function.many.once (/home/nkunkel/ssb-server/node_modules/obv/index.js:39:7) at /home/nkunkel/ssb-server/node_modules/flumelog-offset/inject.js:15:11 at drain (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:20:5) at Object.write [as append] (/home/nkunkel/ssb-server/node_modules/append-batch/index.js:30:41)```
This is happening here when the length of log.offset is larger than the largest acceptable value for buf.writeUInt32BE, 4294967295 or a log.offset of 4.29ish gb or less. @staltz mentioned size could be an issue upthread and if your log.offset file is 5gb, that could be why.
I'm not sure the what can be done to fix it though. (also very aware that I could be wrong)
this might be relevant
https://stackoverflow.com/questions/14730980/nodejs-write-64bit-unsigned-integer-to-buffer
The database is about 5GB big.
@NiklasKunkel Could you clarify what is 5GB big? Is it the whole ~/.ssb
folder or is it the file ~/.ssb/flume/log.offset
. The former sounds okay, the latter is concerning.
On Mon, Sep 09, 2019 at 02:42:07AM -0700, André Staltz wrote:
The database is about 5GB big.
@NiklasKunkel Could you clarify what is 5GB big? Is it the whole
~/.ssb
folder or is it the file~/.ssb/flume/log.offset
. The former sounds okay, the latter is concerning.--
@staltz @NiklasKunkel
I was able to reproduce this with the following script:
const CreateTestSbot = require('scuttle-testbot')
const sbot = CreateTestSbot({name: 'bigSbot'})
function post () {
const buf = Buffer.alloc(1200)
buf.fill(0)
const msg = buf.toString()
sbot.publish({type: 'post', text: msg}, function (err, msg) {
if(err) throw err
console.log(sbot.since().since)
post()
})
}
post()
It took awhile (about 12 hrs) but once the log.offset
file is greater than 4294967295 it throws the same error. the output below shows a few console.log's of the log.offset length after a successful append and then throws the error when it's too large for bug.writeUInt32BE(val, offset)
.
4294921075
4294928806
4294936537
4294944268
4294951999
internal/buffer.js:35
throw new ERR_OUT_OF_RANGE('value', `>= ${min} and <= ${max}`, value);
^
RangeError [ERR_OUT_OF_RANGE]: The value of "value" is out of range. It must be >= 0 and <= 4294967295. Received 4294967465
at checkInt (internal/buffer.js:35:11)
at writeU_Int32BE (internal/buffer.js:619:3)
at Buffer.writeUInt32BE (internal/buffer.js:632:10)
at Object.encode (/home/austin/scribbles/bigSbot/node_modules/flumelog-offset/frame/offset-codecs.js:9:11)
at Object.frame (/home/austin/scribbles/bigSbot/node_modules/flumelog-offset/frame/recoverable.js:23:19)
at /home/austin/scribbles/bigSbot/node_modules/flumelog-offset/inject.js:19:26
at Function.many.once (/home/austin/scribbles/bigSbot/node_modules/obv/index.js:39:7)
at /home/austin/scribbles/bigSbot/node_modules/flumelog-offset/inject.js:15:11
at drain (/home/austin/scribbles/bigSbot/node_modules/append-batch/index.js:20:5)
at Object.write [as append] (/home/austin/scribbles/bigSbot/node_modules/append-batch/index.js:30:41)
it looks like flumelog-offset
has encode/decode for 64 bit using offsetCodec[53] but there is no capability currently to switch encodings if an int is to large, the default is 32.
i'm also unsure what happens when you switch encodings to something other than the initially supplied value. would that mess with anything? my initial thought would be no, but want to double check.
for others reading, am i on the right track with this?
aside: is there a better way to generate a large log.offset file? this took a long time and if there is a faster way to generate a valid log.offset it could be useful.
The database is about 5GB big.
@NiklasKunkel Could you clarify what is 5GB big? Is it the whole
~/.ssb
folder or is it the file~/.ssb/flume/log.offset
. The former sounds okay, the latter is concerning.
It might be obvious at this point but it was indeed the log.offset that took up the majority of the 5GB file size.
it could have really saved me some time to read the flumelog-offset readme more carefully...
offsetCodec: { // default is require('./frame/offset-codecs')[32]
byteWidth, // with the default offset-codec, the file can have
encode, // a size of 4GB max.
decodeAsync
}
So is this really just how ssb behaves once a log offset has grown substantially large? What are the limiting factors for increasing this threshold? I have an application that publishes a significant amount of messages over time. There must be a better solution than reseting the ssb ledger every 6 months.
@NiklasKunkel
So is this really just how ssb behaves once a log offset has grown substantially large?
It would appear so, this is configurable at lower levels in the database by changing the OffsetCodec
but it doesn't look like it's exposed at higher levels.
you might try patching it using something like patch-package and passing a different offsetCodec
here in the underlying ssb-db
dependency.
something like this:
var log = OffsetLog(path.join(dirname, 'log.offset'), { blockSize: 1024 * 16, codec, offsetCodec: 53 })
might be good to wait for more knowledgeable folks to chime in and comment on if that's a good idea or not though.
Is this still relevant? If so, what is blocking it? Is there anything you can do to help move it forward?
@NiklasKunkel were you able to solve this issue? I'd be interested in hearing about how you worked through this.
I think this is not fixed, and this bug has lead to an outage of some very critical infrastructure. Please reopen and address. https://forum.makerdao.com/t/11-25-20-oracle-outage-post-mortem/5547