jbmusso / gremlin-javascript

JavaScript tools for graph processing in Node.js and the browser inspired by the Apache TinkerPop API
MIT License
214 stars 63 forks source link

Cannot read property 'messageStream' of undefined #47

Closed davidcrouch closed 8 years ago

davidcrouch commented 8 years ago

UPDATE: The problem I'm seeing may be related to Issue #29 and possibly addressed in PR #31 (or at least provide a better/safer foundation for supporting what I'm trying to do).

I've created a NodeJs utility for uploading multiple files to a Neo4j database via Tinkerpop 3 (one request per file). Essentially, a vertex with a "Content" property is created that represents the file.

I've seen the error sometimes appear after uploading 800+ files but on this occasion it was after just 30 files i.e. doesn't appear to be overloading buffer maximums. I was able to remove all the other files and reproduce it with the one text file in question. The files are almost all ".js" text files so they are not large.

I read the contents of the file with:-

var contents = fs.readFileSync(sourceName, 'utf8');

The Gremlin script adds a vertex with a 'Content' property containing the contents of the file. When I submit the script using the gremlin client "execute" method I receive the following:-

TypeError: Cannot read property 'messageStream' of undefined
    at GremlinClient.handleProtocolMessage (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:153:51)
    at WebSocketGremlinConnection.<anonymous> (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:120:23)
    at emitOne (events.js:78:13)
    at WebSocketGremlinConnection.emit (events.js:170:7)
    at WebSocketGremlinConnection.handleMessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:69:12)
    at WebSocket._EventEmitter.WebSocketGremlinConnection._this.ws.onmessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:46:20)
    at WebSocket.onMessage (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:418:14)
    at emitTwo (events.js:88:13)
    at WebSocket.emit (events.js:173:7)
    at Receiver.onbinary (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:823:10)

I don't believe the problem is with the script since it can successfully complete for 1000s of transactions before seeing this error.

Here is my yaml file:-

threadPoolWorker: 2
gremlinPool: 8
scriptEvaluationTimeout: 30000
serializedResponseTimeout: 30000
channelizer: org.apache.tinkerpop.gremlin.server.channel.WebSocketChannelizer
graphs: {
  graph: conf/itc-neo4j.properties}
plugins:
  - tinkerpop.tinkergraph
scriptEngines: {
  gremlin-groovy: {
    imports: [java.lang.Math, com.itc.steps.*, com.itc.strategy.*, com.itc.traversal.*, com.itc.utils.*, com.itc.Constants],
    staticImports: [java.lang.Math.PI],
    scripts: [scripts/empty-sample.groovy]},
  nashorn: {
    imports: [java.lang.Math, com.itc.steps.*, com.itc.strategy.*, com.itc.traversal.*, com.itc.utils.*, com.itc.Constants],
    staticImports: [java.lang.Math.PI]}}
serializers:
  - { className: org.apache.tinkerpop.gremlin.driver.ser.GryoMessageSerializerV1d0 }                                             # application/vnd.gremlin-v1.0+gryo
  - { className: org.apache.tinkerpop.gremlin.driver.ser.GryoMessageSerializerV1d0, config: { serializeResultToString: true }}   # application/vnd.gremlin-v1.0+gryo-stringd
  - { className: org.apache.tinkerpop.gremlin.driver.ser.GraphSONMessageSerializerGremlinV1d0 }                                  # application/vnd.gremlin-v1.0+json
  - { className: org.apache.tinkerpop.gremlin.driver.ser.GraphSONMessageSerializerV1d0 }                                         # application/json
processors:
  - { className: org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor, config: { sessionTimeout: 28800000 }}
metrics: {
  consoleReporter: {enabled: true, interval: 180000},
  csvReporter: {enabled: true, interval: 180000, fileName: /tmp/gremlin-server-metrics.csv},
  jmxReporter: {enabled: true},
  slf4jReporter: {enabled: true, interval: 180000},
  gangliaReporter: {enabled: false, interval: 180000, addressingMode: MULTICAST},
  graphiteReporter: {enabled: false, interval: 180000}}
threadPoolBoss: 1
maxInitialLineLength: 4096
maxHeaderSize: 8192
maxChunkSize: 8192
maxContentLength: 8192000
maxAccumulationBufferComponents: 8192
resultIterationBatchSize: 64
writeBufferLowWaterMark: 65535
writeBufferHighWaterMark: 65536
ssl: {
  enabled: false}

On the server I'm seeing the error below. The "PooledUnsafeDirectByteBuf" tells me that the message is being submitted by the client in the wrong format:-

[WARN] AbstractGraphSONMessageSerializerV1d0 - Request [PooledUnsafeDirectByteBuf(ridx: 1054, widx: 1054, cap: 1071)] could not be deserialized by org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0.
1749352 [gremlin-server-worker-2] WARN org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0  - Request [PooledUnsafeDirectByteBuf(ridx: 1054, widx: 1054, cap: 1071)] could not be deserialized by org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0.
[WARN] OpSelectorHandler - Invalid OpProcessor requested [null]
org.apache.tinkerpop.gremlin.server.op.OpProcessorException: Invalid OpProcessor requested [null]
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:84)
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:50)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.http.websocketx.WebSocketServerProtocolHandler$1.channelRead(WebSocketServerProtocolHandler.java:146)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
        at java.lang.Thread.run(Thread.java:745)
1749357 [gremlin-server-worker-2] WARN org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler  - Invalid OpProcessor requested [null]
org.apache.tinkerpop.gremlin.server.op.OpProcessorException: Invalid OpProcessor requested [null]
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:84)
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:50)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.http.websocketx.WebSocketServerProtocolHandler$1.channelRead(WebSocketServerProtocolHandler.java:146)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
        at java.lang.Thread.run(Thread.java:745)

I tried to attach the file causing the problem but the Github Issue page gave an error saying "we don't support that file type". This provides a hint that perhaps the mime type is defaulting to the wrong value causing the server to fail.

The file is the "AUTHORS" file (no suffix) from the NPM "Acorn" node module and simply contains:-

List of Acorn contributors. Updated before every release.

Adrian Rakovsky
Alistair Braidwood
Andres Suarez
Aparajita Fishman
Arian Stolwijk
Artem Govorov
Brandon Mills
Charles Hughes
Conrad Irwin
David Bonnet
Forbes Lindesay
Gilad Peleg
impinball
Ingvar Stepanyan
Jiaxing Wang
Johannes Herr
Jürg Lehni
keeyipchan
krator
Marijn Haverbeke
Martin Carlberg
Mathias Bynens
Mathieu 'p01' Henri
Max Schaefer
Max Zerzouri
Mihai Bazon
Mike Rennie
Nick Fitzgerald
Oskar Schöldström
Paul Harper
Peter Rust
PlNG
r-e-d
Rich Harris
Sebastian McKenzie
zsjforcn
dmill-bz commented 8 years ago

Does the server output have anything else before the error? Like a recap of the script submitted or maybe a warning?

davidcrouch commented 8 years ago

No, I don't think so but I have include some messages before the warning, which are typical:-

[INFO] MarkerIgnoringBase - type=METER, name=org.apache.tinkerpop.gremlin.server.GremlinServer.op.control, count=0, mean_rate=0.0, m1=0.0, m5=0.0, m15=0.0, rate_unit=events/second
721101 [metrics-logger-reporter-thread-1] INFO org.apache.tinkerpop.gremlin.server.Settings$Slf4jReporterMetrics  - type=METER, name=org.apache.tinkerpop.gremlin.server.GremlinServer.op.control, count=0, mean_rate=0.0, m1=0.0, m5=0.0, m15=0.0, rate_unit=events/second
[INFO] MarkerIgnoringBase - type=TIMER, name=org.apache.tinkerpop.gremlin.server.GremlinServer.op.eval, count=293, min=0.404761, max=385.862715, mean=47.46506880887372, stddev=57.49093624579264, median=32.301441, p75=68.283549, p95=150.65201160000004, p98=212.85775324000005, p99=269.2705142200002, p999=385.862715, mean_rate=0.4662758243743828, m1=0.014225843226068353, m5=0.2877557007102771, m15=0.30764531599057615, rate_unit=events/second, duration_unit=milliseconds
721101 [metrics-logger-reporter-thread-1] INFO org.apache.tinkerpop.gremlin.server.Settings$Slf4jReporterMetrics  - type=TIMER, name=org.apache.tinkerpop.gremlin.server.GremlinServer.op.eval, count=293, min=0.404761, max=385.862715, mean=47.46506880887372, stddev=57.49093624579264, median=32.301441, p75=68.283549, p95=150.65201160000004, p98=212.85775324000005, p99=269.2705142200002, p999=385.862715, mean_rate=0.4662758243743828, m1=0.014225843226068353, m5=0.2877557007102771, m15=0.30764531599057615, rate_unit=events/second, duration_unit=milliseconds
[WARN] AbstractGraphSONMessageSerializerV1d0 - Request [PooledUnsafeDirectByteBuf(ridx: 1054, widx: 1054, cap: 1071)] could not be deserialized by org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0.
737291 [gremlin-server-worker-1] WARN org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0  - Request [PooledUnsafeDirectByteBuf(ridx: 1054, widx: 1054, cap: 1071)] could not be deserialized by org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0.
[WARN] OpSelectorHandler - Invalid OpProcessor requested [null]
org.apache.tinkerpop.gremlin.server.op.OpProcessorException: Invalid OpProcessor requested [null]
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:84)
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:50)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
dmill-bz commented 8 years ago

Ok so all in all it seems like the issue is somewhere between the gremlin-javascript message building phase and gremlin-server selecting the OpPorcessor. So I guess the next step would be to log the following var : https://github.com/jbmusso/gremlin-javascript/blob/master/src/GremlinClient.js#L193

Is this random or always on that file? I'm thinking this may be a case of https://github.com/jbmusso/gremlin-javascript/blob/master/src/GremlinClient.js#L201 not playing nicely with a character from that file. so perhaps also log the binary messages.

On our end we should try to download that file and run tests as well (this file right? : https://github.com/ternjs/acorn/blob/master/AUTHORS ).

Which version of gremlin-server are you using?

In any event this might be the good time to take care of #20. Thoughts @jbmusso ?

davidcrouch commented 8 years ago

Yes, I agree - I think it gets caught up on a character sequence in the file. But I think the opProcessor error is a symptom of the serializer not being able to deserialize the message (PooledUnsafeDirectByteBuf). I am going to do some more testing because it's not too hard to find other files that cause the problem.

jbmusso commented 8 years ago

Thanks for sending a detailed issue, I'll try to have a look at it this evening. We might have to ping Stephen on this one.

On Tuesday, 12 April 2016, David Crouch notifications@github.com wrote:

Yes, I agree - I think it gets caught up on a character sequence in the file. I am going to do some more testing because it's not too hard to find other files.

  • Yes, it always occurs on 'that' file, even when the number of files being uploaded is changed i.e. doesn't appear to be affected by load.
  • Yes, it AUTHORS from the Acorn node module.
  • We're using Gremlin Server 3.0.0

— You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub https://github.com/jbmusso/gremlin-javascript/issues/47#issuecomment-208812517

Jean-Baptiste

davidcrouch commented 8 years ago

For kicks I tried reading the raw contents of the file with this:-

var contents = fs.readFileSync(sourceName);

...and got this error message below indicating that the message type is not supported. I thought I had read somewhere that Gremlin client had been modified recently to support binary data.

Is this not correct? Am I doing something wrong? Do I need to explicitly set the Mime type to something other than the default?

BTW, the "runAs" in the script below is a custom extension, which essentially wraps standard Gremlin.

2016-04-12T16:03:04.960Z - error: error when executing script: _itcSource = g.runAs(user_token).V(89530).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Items', 'target_type_id', 365,'Name',_itcName,'Content',_itcContent).valueMap(true) Error: Property value [{type=Buffer, data=[76, 105, 115, 116, 32, 111, ........  

   ........., 114, 99, 110, 10]}] is of type class java.util.LinkedHashMap is not supported (Error 500)
    at GremlinClient.handleProtocolMessage (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:174:39)
    at WebSocketGremlinConnection.<anonymous> (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:120:23)
    at emitOne (events.js:78:13)
    at WebSocketGremlinConnection.emit (events.js:170:7)
    at WebSocketGremlinConnection.handleMessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:69:12)
    at WebSocketGremlinConnection._this.ws.onmessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:46:20)
    at WebSocket.onMessage (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:418:14)
    at emitTwo (events.js:88:13)
    at WebSocket.emit (events.js:173:7)
    at Receiver.onbinary (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:823:10)
dmill-bz commented 8 years ago

I'm not sure I really understand what you mean but to clarify : gremlin-javascript sends the messages in binary but the payload should still be in JSON. This is a little different from supporting a binary payload. Here the server is receiving your javascript binary map and is treating it like a LinkedHashMap which it seems to choke on. You could base64 it to a string instead.

jbmusso commented 8 years ago

I read the thread carefully, and I don't have a single clue of what could be going wrong. Bleh.

The error indicates that when handling a server message, the client fails to find the corresponding pending command (= sent query) for that message. The client looks into a dictionary of pending commands (this.commands) keyed by requests uuids (= requestId), but in the present case the id appears to be undefined so the client crashes when attempting to push data to the corresponding stream. There could be an issue where Gremlin server returns an empty message for that specific command that you sent, but that's weird. Could you edit node_modules/gremlin/lib/GremlinClient.js and console.log(rawMessage) at line 148? (assuming you're using gremlin-javascript v2.3.1). It'd be interesting to see what the server returns.

davidcrouch commented 8 years ago

I added the following log messages to GremlinClient:-

    key: 'sendMessage',
    value: function sendMessage(message) {
      var serializedMessage = this.options.accept + JSON.stringify(message);
      console.log("sendMessage: serializedMessage: ", serializedMessage);
    key: 'handleProtocolMessage',
    value: function handleProtocolMessage(message) {
      var data = message.data;

      var buffer = new Buffer(data, 'binary');
      var rawMessage = JSON.parse(buffer.toString('utf-8'));
      console.log("handleProtocolMessage: rawMessage: ", rawMessage);

I ran essentially the same test, which generated the following log. I have included more log than necessary so you can see some successful communication requests before the failure. The important one is that it successfully uploads ".travis.yml" and then later fails on "AUTHORS".

2016-04-13T02:17:32.210Z - debug: statSync: found in Itc:  \Applications\Simple React\node_modules
2016-04-13T02:17:32.211Z - info: Uploading  node_modules\acorn  to  \Applications\Simple React\node_modules\acorn
2016-04-13T02:17:32.216Z - info: 
Name: undefined, Script: _itcSource = g.runAs(user_token).V(1276).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Categories', 'target_type_id', 350,'Name',_itcName).valueMap(true) 

sendMessage: serializedMessage:  application/json{"requestId":"e103a290-011d-11e6-86c4-93407318cb37","processor":"","op":"eval","args":{"gremlin":"_itcSource = g.runAs(user_token).V(1276).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Categories', 'target_type_id', 350,'Name',_itcName).valueMap(true)","bindings":{"_itcName":"acorn","user_token":"1.g37C+qsr9Cuq3WwOItvTwmxZ7lBM6SbRp9i/KtiijpE"},"accept":"application/json","language":"gremlin-groovy"}}
2016-04-13T02:17:32.591Z - debug: mkdirSync: returning new dir: 
handleProtocolMessage: rawMessage:  { requestId: 'e103a290-011d-11e6-86c4-93407318cb37',
  status: { message: '', code: 200, attributes: {} },
  result: { data: [ [Object] ], meta: {} } }
2016-04-13T02:17:32.592Z - info: Uploading  node_modules\acorn\.travis.yml  to  \Applications\Simple React\node_modules\acorn\.travis.yml
2016-04-13T02:17:32.594Z - debug: openSync: return  3
2016-04-13T02:17:32.594Z - debug: fstatSync: return  dev=-1206588991, mode=33206, nlink=1, uid=0, gid=0, rdev=0, blksize=undefined, ino=844424930419809, size=69, blocks=undefined, atime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), mtime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), ctime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), birthtime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time)
2016-04-13T02:17:32.602Z - debug: fsReadSync: return  69
2016-04-13T02:17:32.602Z - debug: closeSync: return  undefined
2016-04-13T02:17:32.602Z - debug: readFileSync: returning content from local:  node_modules\acorn\.travis.yml
2016-04-13T02:17:32.607Z - info: 
Name: undefined, Script: _itcSource = g.runAs(user_token).V(89990).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Items', 'target_type_id', 365,'Name',_itcName,'Content',_itcContent).valueMap(true) 

sendMessage: serializedMessage:  application/json{"requestId":"e13f4c00-011d-11e6-86c4-93407318cb37","processor":"","op":"eval","args":{"gremlin":"_itcSource = g.runAs(user_token).V(89990).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Items', 'target_type_id', 365,'Name',_itcName,'Content',_itcContent).valueMap(true)","bindings":{"_itcName":".travis.yml","_itcContent":"language: node_js\nsudo: false\nnode_js:\n  - '0.10'\n  - '0.12'\n  - '4'\n","user_token":"1.g37C+qsr9Cuq3WwOItvTwmxZ7lBM6SbRp9i/KtiijpE"},"accept":"application/json","language":"gremlin-groovy"}}
handleProtocolMessage: rawMessage:  { requestId: 'e13f4c00-011d-11e6-86c4-93407318cb37',
  status: { message: '', code: 200, attributes: {} },
  result: { data: [ [Object] ], meta: {} } }
2016-04-13T02:17:33.811Z - info: Files uploaded:  0
2016-04-13T02:17:33.812Z - info: Uploading  node_modules\acorn\AUTHORS  to  \Applications\Simple React\node_modules\acorn\AUTHORS
2016-04-13T02:17:33.813Z - debug: openSync: return  3
2016-04-13T02:17:33.814Z - debug: fstatSync: return  dev=-1206588991, mode=33206, nlink=1, uid=0, gid=0, rdev=0, blksize=undefined, ino=844424930419854, size=612, blocks=undefined, atime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), mtime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), ctime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time), birthtime=Tue Apr 12 2016 19:15:27 GMT-0700 (Pacific Daylight Time)
2016-04-13T02:17:33.815Z - debug: fsReadSync: return  612
2016-04-13T02:17:33.815Z - debug: closeSync: return  undefined
2016-04-13T02:17:33.816Z - debug: readFileSync: returning content from local:  node_modules\acorn\AUTHORS
2016-04-13T02:17:33.819Z - info: 
Name: undefined, Script: _itcSource = g.runAs(user_token).V(89990).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Items', 'target_type_id', 365,'Name',_itcName,'Content',_itcContent).valueMap(true) 

sendMessage: serializedMessage:  application/json{"requestId":"e1f862d0-011d-11e6-86c4-93407318cb37","processor":"","op":"eval","args":{"gremlin":"_itcSource = g.runAs(user_token).V(89990).next();g.runAs(user_token).addV('source_id', _itcSource.id(), 'rel_name', 'Items', 'target_type_id', 365,'Name',_itcName,'Content',_itcContent).valueMap(true)","bindings":{"_itcName":"AUTHORS","_itcContent":"List of Acorn contributors. Updated before every release.\n\nAdrian Rakovsky\nAlistair Braidwood\nAndres Suarez\nAparajita Fishman\nArian Stolwijk\nArtem Govorov\nBrandon Mills\nCharles Hughes\nConrad Irwin\nDavid Bonnet\nForbesLindesay\nForbes Lindesay\nGilad Peleg\nimpinball\nIngvar Stepanyan\nJesse McCarthy\nJiaxing Wang\nJoel Kemp\nJohannes Herr\nJürg Lehni\nkeeyipchan\nKevin Kwok\nkrator\nMarijn Haverbeke\nMartin Carlberg\nMathias Bynens\nMathieu 'p01' Henri\nMax Schaefer\nMax Zerzouri\nMihai Bazon\nMike Rennie\nNick Fitzgerald\nOskar Schöldström\nPaul Harper\nPeter Rust\nPlNG\nr-e-d\nRich Harris\nSebastian McKenzie\nTimothy Gu\nzsjforcn\n","user_token":"1.g37C+qsr9Cuq3WwOItvTwmxZ7lBM6SbRp9i/KtiijpE"},"accept":"application/json","language":"gremlin-groovy"}}
handleProtocolMessage: rawMessage:  { requestId: null,
  status: { message: '', code: 499, attributes: {} },
  result: { data: 'Invalid OpProcessor requested [null]', meta: {} } }
2016-04-13T02:17:33.994Z - error: uncaughtException: Cannot read property 'messageStream' of undefined date=Tue Apr 12 2016 19:17:33 GMT-0700 (Pacific Daylight Time), pid=2224, uid=null, gid=null, cwd=d:\itc\development\itc\itc-dev\node_modules\applications\react\click-event, execPath=D:\nodejs\node.exe, version=v5.2.0, argv=[D:\nodejs\node.exe, d:\itc\development\itc\itc-dev\node_modules\applications\react\click-event\init-modules.js], rss=37949440, heapTotal=32266496, heapUsed=18261144, loadavg=[0, 0, 0], uptime=464947.5003969
TypeError: Cannot read property 'messageStream' of undefined
    at GremlinClient.handleProtocolMessage (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:155:51)
    at WebSocketGremlinConnection.<anonymous> (d:\itc\development\itc\node_modules\gremlin\lib\GremlinClient.js:120:23)
    at emitOne (events.js:78:13)
    at WebSocketGremlinConnection.emit (events.js:170:7)
    at WebSocketGremlinConnection.handleMessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:69:12)
    at WebSocketGremlinConnection._this.ws.onmessage (d:\itc\development\itc\node_modules\gremlin\lib\WebSocketGremlinConnection.js:46:20)
    at WebSocket.onMessage (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:418:14)
    at emitTwo (events.js:88:13)
    at WebSocket.emit (events.js:173:7)
    at Receiver.onbinary (d:\itc\development\itc\node_modules\ws\lib\WebSocket.js:823:10)

And here is the trace from the Gremlin Server log (same as before). The server is having trouble deserializing the message:-

37008443 [gremlin-server-worker-1] WARN org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0  - Request [PooledUnsafeDirectByteBuf(ridx: 1121, widx: 1121,
cap: 1138)] could not be deserialized by org.apache.tinkerpop.gremlin.driver.ser.AbstractGraphSONMessageSerializerV1d0.
[WARN] OpSelectorHandler - Invalid OpProcessor requested [null]
org.apache.tinkerpop.gremlin.server.op.OpProcessorException: Invalid OpProcessor requested [null]
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:84)
        at org.apache.tinkerpop.gremlin.server.handler.OpSelectorHandler.decode(OpSelectorHandler.java:50)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.http.websocketx.WebSocketServerProtocolHandler$1.channelRead(WebSocketServerProtocolHandler.java:146)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
        at java.lang.Thread.run(Thread.java:745)
davidcrouch commented 8 years ago

I ran some more tests and was able to reproduce the problem in other files. Most of the time when a file upload failed I re-ran the same test to confirm it would fail on the same file (when I remembered :-)). The failures were somewhat random on when they would occur i.e. 20 files, 50 files, 70 files into the upload. I captured the log and saved it in these Gists:-

https://gist.github.com/davidcrouch/75d455ecaa07051635f78785fb0ee715 https://gist.github.com/davidcrouch/2e36101dbbe2492d45e85963b8978ddd https://gist.github.com/davidcrouch/bac7b3ceab53c9a8ebda885aba0668e1 https://gist.github.com/davidcrouch/6a4ef1a7e450e5ef5b7e2fa3f597f632 https://gist.github.com/davidcrouch/a11e3757b848e574bec76c6c14f8d9d4

dmill-bz commented 8 years ago

This might be a little tedious but can you try this against gremlin-server 3.1.1? I'm going to run a few tests of my own as well.

davidcrouch commented 8 years ago

Unfortunately migrating to 3.1.1 is not so simple since we have custom traversal strategies that support what we submit on the client e.g. authentication and authorization. However, I'm wondering if this problem can easily be reproduced inside a standard/clean install using a quick and dirty utility? Maybe its a test you could try?

I'm basically walking through a NodeJS node_modules modules directories, reading the contents of each file found inside modules, creating a new vertex and uploading the file contents into a vertex property.

It seems from the tests I've run that something in the payload is causing problems for the Gremlin Server to deserialize, and hence an empty message is returned (requestId = null) causing the Gremlin client to fail.

dmill-bz commented 8 years ago

I set this up locally and get the same result on 3.1.2-SNAPSHOT but no bug using the PHP driver. Here's the PHP request JSON as a reference :

{"requestId":"5aa6640b-f004-4eff-ba5a-00dba61d434d","processor":"","op":"eval","args":{"gremlin":"graph.addVertex('content', B_CONTENT);","bindings":{"B_CONTENT":"List of Acorn contributors. Updated before every release.\n\nAdrian Rakovsky\nAlistair Braidwood\nAndres Suarez\nAparajita Fishman\nArian Stolwijk\nArtem Govorov\nBrandon Mills\nCharles Hughes\nConrad Irwin\nDavid Bonnet\nForbesLindesay\nForbes Lindesay\nGilad Peleg\nimpinball\nIngvar Stepanyan\nJesse McCarthy\nJiaxing Wang\nJoel Kemp\nJohannes Herr\nJürg Lehni\nkeeyipchan\nKevin Kwok\nkrator\nMarijn Haverbeke\nMartin Carlberg\nMathias Bynens\nMathieu 'p01' Henri\nMax Schaefer\nMax Zerzouri\nMihai Bazon\nMike Rennie\nNick Fitzgerald\nOskar Schöldström\nPaul Harper\nPeter Rust\nPlNG\nr-e-d\nRich Harris\nSebastian McKenzie\nTimothy Gu\nzsjforcn\n"}}}

I'm guessing there's a problem with gremlin-javascript binary serialization. I noticed that your failing gists all contain some special chars.

dmill-bz commented 8 years ago

FYI this breaks :

const Gremlin = require('gremlin');

const client = Gremlin.createClient();
client.execute('ö');
davidcrouch commented 8 years ago

What about if you try this?

const Gremlin = require('gremlin');

const client = Gremlin.createClient();
client.execute("g.addV('someChar', aChar)", { aChar:  'ö' });
dmill-bz commented 8 years ago

Same result. I think I'm narrowing down on this issue. If I understand correctly gremlin-server and the binary serialization of the javascript driver are currently expecting utf-8. But javascript Strings are natively utf-16 and we're getting conflicts. The driver needs to make sure it serializes utf-8.

As a demonstration of this, the following fixes the issue (sendMessage()):

var serializedMessage = this.options.accept + JSON.stringify(message);
serializedMessage = unescape(encodeURIComponent(serializedMessage));

I haven't really fully tested this in browser but a manual nodejs test works. @davidcrouch let me know if that change fixes things for you.

@jbmusso it might be wise to use some dependency here as they will probably cover more cases than we can imagine (though I know the thought of one more dependency is a pain for browser implementations). Or we can fully test the fix above and just roll with that, but I believe there are going to be some issues with the above as per : http://stackoverflow.com/questions/19752988/javascript-charat-breaking-multibyte-character-string and I found some other edge cases with encodeURIComponent that could be undesirable (namely around HTML elements).

davidcrouch commented 8 years ago

Yes, the fix appears to be working for me. I've tested it on 3 of the failed Gists and it now successfully completes for those. I'm now in the process of running a large test (~2000 files) and will let you know how it goes.

jbmusso commented 8 years ago

Bummer :). Thanks for investigating on this. I was about to add a comment as another user reported issues with v2.3.1 when sending accentuated characters. I'm not aware of any lightweight dependency that would make it easy to support this both in Node.js and browser environments, so I'll have to investigate. A quick workaround, which I don't like much, is to use v2.2.x of the client.

dmill-bz commented 8 years ago

We can always implement the above fix in the meantime. I've run the tests in both node and browser and the above works. It might not cover 100% of all cases but it'll be heaps better than currently. I'll make a PR on the off chance it's worth merging.

davidcrouch commented 8 years ago

FYI, I ran a test for uploading the contents of about 4000 files and it ran with no problems. The files were taken from modules typically found in the NodeJS node_modules directory.

jbmusso commented 8 years ago

I appreciate your help. The fix (+ test) has been published on npm as v2.3.2.