Clinic v0.6.2 / Node v8.9.4: Error: Invalid JSON (Unexpected "p" at position 24584 in state STOP)

[darkpixel]

This pops up after hanging at 'analyzing data' for a few seconds:

analysing data
events.js:183
      throw er; // Unhandled 'error' event
      ^

Error: Invalid JSON (Unexpected "p" at position 24584 in state STOP)
    at Parser.proto.charError (/home/aaron/code/mspdna-ssh/node_modules/jsonparse/jsonparse.js:90:16)
    at Parser.proto.write (/home/aaron/code/mspdna-ssh/node_modules/jsonparse/jsonparse.js:154:23)
    at Stream.<anonymous> (/home/aaron/code/mspdna-ssh/node_modules/JSONStream/index.js:21:12)
    at Stream.stream.write (/home/aaron/code/mspdna-ssh/node_modules/through/index.js:26:11)
    at TraceEventDecoder._transform (/home/aaron/code/mspdna-ssh/node_modules/@nearform/clinic-doctor/format/trace-event-decoder.js:114:19)
    at TraceEventDecoder.Transform._read (_stream_transform.js:186:10)
    at TraceEventDecoder.Transform._write (_stream_transform.js:174:12)
    at doWrite (_stream_writable.js:387:12)
    at writeOrBuffer (_stream_writable.js:373:5)
    at TraceEventDecoder.Writable.write (_stream_writable.js:290:11)
19:12:39 ⌂131% [aaron@ripley:~/code/mspdna-ssh] [mspdna] develop(+2861/-42)* 1 ± 

The instructions say it would be super helpful if I tell clinic to upload some data to the cloud to help with debugging. I'm hesitant to do that on a private project that has SSH keys loaded into memory. What's "the cloud", where's the data going, and who gets to see it? ;)

[AndreasMadsen]

Properly this is because you use Node v8.9.4. There are some issues with Node v8.9.4 that will be fixed in Node 8.10.0. Unfortunately, that hasn't been released yet. Please try Node v9.4.0 and see if that helps.

What's "the cloud", where's the data going, and who gets to see it? ;)

The cloud is our Amazon server that is in the US (@mafintosh confirm please) and only the clinic team gets to see it.

I think the more important question is what gets uploaded. There are three files, the information is not sensitive at all. The upload code is in https://github.com/nearform/node-clinic/blob/master/lib/tar-and-upload.js you can confirm yourself that it only uploads the clinic data. The clinic data itself contains three files:

• {pid}.clinic-doctor-traceevent: A JSON file containing GC data and execution timing data (inspect it yourself). This is also the file that is partial.
• {pid}.clinic-doctor-systeminfo: A JSON file (inspect it yourself).
• {pid}.clinic-doctor-processstat: A protocol buffer file, containing samples of memory usage, cpu usage, delay, and number of handles. You can see the schema here: https://github.com/nearform/node-clinic-doctor/blob/master/format/process-stat.proto

---

Could you tell me if you have any files called node_trace.2.log?

[mcollina]

How about we put that explanation of the files being uploaded into the README? Seems a valid question.

[darkpixel]

Thanks @AndreasMadsen. I updated to Node 9.5.0 simply because that was the latest version in the 9x tree from nodesource. Let me know if I need to specifically downgrade to 9.4.0 for testing and I'll do it.

I was testing with the 'ssh module' component of my stack earlier, but moved on to doing some work on the 'receiver module' late yesterday, so I decided to test clinic with it.

I got a similar error:

^Canalysing data
events.js:137
      throw er; // Unhandled 'error' event
      ^

Error: Unexpected LEFT_BRACE("{") in state KEY
    at Parser.proto.parseError (/home/aaron/code/mspdna-receiver/node_modules/jsonparse/jsonparse.js:321:16)
    at Parser.proto.onToken (/home/aaron/code/mspdna-receiver/node_modules/jsonparse/jsonparse.js:391:19)
    at Parser.parser.onToken (/home/aaron/code/mspdna-receiver/node_modules/JSONStream/index.js:126:12)
    at Parser.proto.write (/home/aaron/code/mspdna-receiver/node_modules/jsonparse/jsonparse.js:134:28)
    at Stream.<anonymous> (/home/aaron/code/mspdna-receiver/node_modules/JSONStream/index.js:21:12)
    at Stream.stream.write (/home/aaron/code/mspdna-receiver/node_modules/through/index.js:26:11)
    at TraceEventDecoder._transform (/home/aaron/code/mspdna-receiver/node_modules/@nearform/clinic-doctor/format/trace-event-decoder.js:114:19)
    at TraceEventDecoder.Transform._read (_stream_transform.js:185:10)
    at TraceEventDecoder.Transform._write (_stream_transform.js:173:12)
    at doWrite (_stream_writable.js:407:12)
10:00:42 ⌂115% [aaron@ripley:~/code/mspdna-receiver] [mspdna] develop(+2570/-170)* 1 ± node --version
v9.5.0

The single run of clinic produced 10 .clinic-doctor folders. Running clinic upload suggests I run clinic upload 13242.clinic-doctor. That folder doesn't exist, so I think the text is just an example. If it's tracking a 'last run' or something, then it mis-detected it.

I'm guessing the multiple folders are for each process spawned by the cluster module which I was using in both my ssh module and receiver module. I decided now would be a good time to migrate away from it, so I ripped it out and I can't seem to duplicate any of the errors. But the end result is a report that says there was an unknown issue.

I'm going to rip the cluster module out of my ssh module and try testing again with that. When I ran clinic against my ssh module I was able to get a report back occasionally with an event loop delay when my box was under a ton of load.

[davidmarkclements]

ahhhh so this tells me we need to either

1. Support the cluster module
2. Be explicit that node-clinic is for single process profiling (as is clinic flame/0x and I assume our additional upcoming tools)

[davidmarkclements]

In the second case we could detect usage of the cluster module and then exit with an error

[darkpixel]

After hammering away without the cluster module, I can't seem to hit any errors in my ssh module. In my receiver module which is basically an express app that received large (up to ~2 MB) chunks of JSON data, clinic continually reports that "Unknown issue" from the screenshot. Any idea what that might be?

[davidmarkclements]

oh that's awesome - the unknown issue means you've either found a new problem or you've found an edge case that we could use to tune our statistical algorithms. Can you provide an isolated case?

[darkpixel]

Sure--you want me to run it and upload the data? Or are you asking if I might have an idea of what the unknown issue is?

[darkpixel]

Uploaded: ce48307f83bee7e5cc865e20109f1d77b18b2e847f9cd06c25e2852a5e98cbf2

[AndreasMadsen]

I looked at the data, it appears that you have both an I/O issue and a GC issue. So that is confusing our classifier a bit.

Regarding the cluster issue, in terms of supporting clusters there are two options:

• we can just profile the master process (easy, but properly not what you want)
• we can profile all processes (also easy, but requires trace_events: add file pattern cli option nodejs/node#18480) – What will be confusing is that by default the master process will be analyzed, so the user will have to manually call clinic doctor --visualize-only pid.clinic-doctor to analyze the other processes.

[AndreasMadsen]

Ref: https://github.com/nearform/node-clinic-doctor/issues/102 (cluster issue)

[mafintosh]

Node 8.10.0 has been released and clinic seems to run great on it. The cluster issue is still relevant.

[AndreasMadsen]

@mafintosh The nodejs/node#14802 issue is also still relevant and could be the cause of some of these issues.

[davisjam]

Similar issue on v9.11.1 using the Node-DC-EIS workload.

(23:12:38) jamie@woody ~/Desktop/node-profiling/benchmarks/node-dc/Node-DC-EIS/Node-DC-EIS-cluster $ export CPU_COUNT=1; ~/Desktop/floss/node-clinic/bin.js doctor -- node server-cluster.js 
Warning: Trace event is an experimental feature and could change at any time.
********************************
Server running at port: 9000
********************************
Setting up cluster with 1 Master (pid: 8843) and 1 workers..
Warning: Trace event is an experimental feature and could change at any time.
Worker:8854 is online
(node:8854) DeprecationWarning: `open()` is deprecated in mongoose >= 4.11.0, use `openUri()` instead, or set the `useMongoClient` option if using `connect()` or `createConnection()`. See http://mongoosejs.com/docs/connections.html#use-mongo-client
Mongoose connected to the database
Constructing list of first names
Constructing list of last names
Constructing list of Addresses
(node:8854) DeprecationWarning: Mongoose: mpromise (mongoose's default promise library) is deprecated, plug in your own promise library instead: http://mongoosejs.com/docs/promises.html
^Canalysing data
events.js:165
      throw er; // Unhandled 'error' event
      ^

Error: Unexpected COMMA(",") in state VALUE
    at Parser.proto.parseError (/home/jamie/Desktop/floss/node-clinic/node_modules/jsonparse/jsonparse.js:321:16)
    at Parser.proto.onToken (/home/jamie/Desktop/floss/node-clinic/node_modules/jsonparse/jsonparse.js:382:19)
    at Parser.parser.onToken (/home/jamie/Desktop/floss/node-clinic/node_modules/JSONStream/index.js:126:12)
    at Parser.proto.write (/home/jamie/Desktop/floss/node-clinic/node_modules/jsonparse/jsonparse.js:139:34)
    at Stream.<anonymous> (/home/jamie/Desktop/floss/node-clinic/node_modules/JSONStream/index.js:21:12)
    at Stream.stream.write (/home/jamie/Desktop/floss/node-clinic/node_modules/through/index.js:26:11)
    at TraceEventDecoder._transform (/home/jamie/Desktop/floss/node-clinic/node_modules/@nearform/clinic-doctor/format/trace-event-decoder.js:114:19)
    at TraceEventDecoder.Transform._read (_stream_transform.js:185:10)
    at TraceEventDecoder.Transform._write (_stream_transform.js:173:12)
    at doWrite (_stream_writable.js:410:12)
Emitted 'error' event at:
    at Parser.parser.onError (/home/jamie/Desktop/floss/node-clinic/node_modules/JSONStream/index.js:140:12)
    at Parser.proto.parseError (/home/jamie/Desktop/floss/node-clinic/node_modules/jsonparse/jsonparse.js:321:8)
    at Parser.proto.onToken (/home/jamie/Desktop/floss/node-clinic/node_modules/jsonparse/jsonparse.js:382:19)
    [... lines matching original stack trace ...]
    at TraceEventDecoder.Transform._write (_stream_transform.js:173:12)

[BridgeAR]

Neither bubbleprof nor doctor support cluster and will now throw an error if cluster.fork() is called.

Therefore I am closing this as resolved.