Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unexpected token u #143

Closed
tanqhnguyen opened this issue May 9, 2012 · 22 comments
Closed

Unexpected token u #143

tanqhnguyen opened this issue May 9, 2012 · 22 comments

Comments

@tanqhnguyen
Copy link

I am having many of this errors on my log.

I am using nodejs 0.6.17, expressjs 2.5.9 (with cluster) and faye 0.8.2 with redis 2.4.8

I am not sure what is it and how to fix it?

2012-05-09 16:50:36 [ERROR] [Faye.NodeAdapter] Unexpected token u
Backtrace:
SyntaxError: Unexpected token u
    at Object.parse (native)
    at Object._callWithParams (/opt/3_1/node_modules/faye/node/faye-node.js:2211:26)
    at Object.handle (/opt/3_1/node_modules/faye/node/faye-node.js:2153:19)
    at HTTPServer.<anonymous> (/opt/3_1/node_modules/faye/node/faye-node.js:2125:52)
    at HTTPServer.emit (events.js:70:17)
    at HTTPParser.onIncoming (http.js:1572:12)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:91:29)
    at Socket.ondata (http.js:1468:22)
    at TCP.onread (net.js:374:27)
@jcoglan
Copy link
Collaborator

jcoglan commented May 9, 2012

Is this a duplicate of #135?

@tanqhnguyen
Copy link
Author

I am serving the application directly without using nginx as the proxy.

@jcoglan
Copy link
Collaborator

jcoglan commented May 9, 2012

In that case I'm going to need some example code to demonstrate this. Can you put an example on GitHub?

@tanqhnguyen
Copy link
Author

It seems to happen randomly, I will try to reproduce it and give you the example code. Thanks for the quick replies.

@jcoglan
Copy link
Collaborator

jcoglan commented May 9, 2012

If you can find out what the input to JSON.parse() is that's making it fail that would be useful too. But a full example probably better to pin down the root cause.

@tanqhnguyen
Copy link
Author

After observing the servers for a while (After adding some tracking code - line 2211 of faye-node.js)

console.log("Faye _callWithParams");
console.log(params);
var message = JSON.parse(params.message),

The error will be occurred when the params is {}

Faye _callWithParams
{}
2012-05-09 19:25:53 [ERROR] [Faye.NodeAdapter] Unexpected token u
Backtrace:
SyntaxError: Unexpected token u
    at Object.parse (native)
    at Object._callWithParams (/opt/3_1/node_modules/faye/node/faye-node.js:2213:26)
    at Object.handle (/opt/3_1/node_modules/faye/node/faye-node.js:2153:19)
    at HTTPServer.<anonymous> (/opt/3_1/node_modules/faye/node/faye-node.js:2125:52)
    at HTTPServer.emit (events.js:70:17)
    at HTTPParser.onIncoming (http.js:1572:12)
    at HTTPParser.parserOnHeadersComplete [as onHeadersComplete] (http.js:91:29)
    at Socket.ondata (http.js:1468:22)
    at TCP.onread (net.js:374:27)

I wonder why Faye receive a request with no params at all? Maybe It is about expressjs sending wrong messages?

P/S: updated, these are the requests that cause the error

headers:
   { 'user-agent': 'Opera/9.80 (Windows NT 6.0; U; en) Presto/2.7.62 Version/11.01',
     host: 'mydomain.com',
     accept: 'text/html, application/xml;q=0.9, application/xhtml+xml, image/png, image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1',
     'accept-language': 'en,en-US;q=0.9',
     'accept-charset': 'iso-8859-1, utf-8, utf-16, *;q=0.1',
     'accept-encoding': 'deflate, gzip, x-gzip, identity, *;q=0',
     referer: 'http://mydomain.com/chatbox/bc28658ccd3461f761d3bfb3db5d1c23',
     cookie: '__utma=59786367.1441917673.1336595873.1336595873.1336595873.1; __utmb=59786367.1.10.1336595873; __utmc=59786367; __utmz=59786367.1336595873.1.1.utmcsr=misaha.blogspot.com|utmccn=(referral)|utmcmd=referral|utmcct=/2012/04/cabin-in-woods_30.html',
     cookie2: '$Version=1',
     'cache-control': 'no-cache',
     connection: 'Keep-Alive, TE',
     te: 'deflate, gzip, chunked, identity, trailers' }

AND

headers:
   { host: 'mydomain.com',
     'user-agent': 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:11.0) Gecko/20100101 Firefox/11.0',
     accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-language': 'pt-br,pt;q=0.8,en-us;q=0.5,en;q=0.3',
     'accept-encoding': 'gzip, deflate',
     'sec-websocket-version': '13',
     origin: 'http://mydomain.com',
     'sec-websocket-key': 'pbUkxnI4ZQvbl1qH5QZfbQ==',
     cookie: 'connect.sid=9iftuCl2K0OJjezcEOMFJV4I.l%2Bs1x7CqGpJVb5PuDGOmRrIeG4E6vl3GryStmi%2BIsC4; __utma=59786367.844784998.1336595412.1336595412.1336595412.1; __utmb=59786367.1.10.1336595412; __utmc=59786367; __utmz=59786367.1336595412.1.1.utmcsr=elektromusic.net|utmccn=(referral)|utmcmd=referral|utmcct=/central.php',
     pragma: 'no-cache',
     'cache-control': 'no-cache, max-age=2592000',
     connection: 'keep-alive' },

I am not sure if it will help or not.

@jcoglan
Copy link
Collaborator

jcoglan commented May 9, 2012

This explains the parsing error, since params.message is undefined:

> JSON.parse(undefined)
SyntaxError: Unexpected token u

I'm now wondering if this is related to #139 or expressjs/express#1097. Obviously, if Faye receives a request with no parameters it should treat the request as invalid, but I'm not sure why the request is empty.

As for the requests you posted, the first is either a GET or POST and entering this section of code:
https://github.com/faye/faye/blob/0.8.2/javascript/adapters/node_adapter.js#L136-147

Check out the values of request.method and request.url, and data on line https://github.com/faye/faye/blob/0.8.2/javascript/adapters/node_adapter.js#L140

The second request is an invalid WebSocket request (it has Sec-WebSocket-Version and Sec-WebSocket-Key, but not Connection: Upgrade and Upgrade: websocket), and therefore being dealt with by the wrong event handler. Either the user agent (Firefox 11) is not sending this header or it's being dropped by an intermediary, possibly Express.

Verify that Faye works if you run it separately from Express, and check the values I mentioned. We might be able to do something about the broken WebSocket but it might be worth checking that Express does not garble it. e.g. have you tried making a plain http://github.com/faye/faye-websocket-node server embedded in an Express app?

@hackable
Copy link

I am facing the same issue when i deployed it on heroku works fine locally on my mac

@jcoglan
Copy link
Collaborator

jcoglan commented May 12, 2012

@hackable Could you gather the information I asked for in the previous comment? Would be really helpful for diagnosis. Also, are you using the Node version, and with or without Express?

@hackable
Copy link

Node 0.6.17 i tried with express and without it on heroku both times it shows

[ERROR] [Faye.NodeAdapter] Unexpected token u

http = require('http')
fs = require('fs')
path = require("path")


#All set, start listening!
port = process.env.PORT or 3000

server = http.createServer((request, response) ->
  console.log "request starting..."
  filePath = "public" + request.url
  filePath = "public/index.html"  if filePath is "public/"
  extname = path.extname(filePath)
  contentType = "text/html"
  switch extname
    when ".js"
      contentType = "text/javascript"
    when ".css"
      contentType = "text/css"
  path.exists filePath, (exists) ->
    if exists
      fs.readFile filePath, (error, content) ->
        if error
          response.writeHead 500
          response.end()
        else
          response.writeHead 200,
            "Content-Type": contentType

          response.end content, "utf-8"
    else
      response.writeHead 404
      response.end()
)

bayeux.attach(server)

server.listen(port)

@jcoglan
Copy link
Collaborator

jcoglan commented May 13, 2012

Found time to put up a Heroku app myself and investigate. The problem is that Heroku does not support WebSocket, but they modify the incoming WebSocket request by removing the Upgrade and Connection headers. This means that the request fires the request instead of upgrade event on the server, and the app treats it as a normal GET request. However, the request has no message in its URI, triggering the call to JSON.parse(undefined).

This does not seem to stop Faye clients from working, but it does result in log noise. I will see about making changes so that Faye's error messaging is more informative, but for now you should do this on the client side to stop it trying to use WebSocket:

client.disable('websocket')

@hackable
Copy link

I can confirm even after putting client.disable('websocket') the errors still show.

@jcoglan
Copy link
Collaborator

jcoglan commented May 14, 2012

Are you calling it immediately after creating the client with new Faye.Client(), and before calling publish() or subscribe()? Does calling client.disable('eventsource') have any effect?

If not, I'm going to need more debugging info from you -- the HTTP method, request path and headers for requests triggering the bug.

@puzrin
Copy link

puzrin commented May 29, 2012

Seems, we become a bit more close to understanding, what happens: fontello/fontello#60 . As you can see - IE9 works with no problems, but all other browsers, wich support ws, fail to connect and fail to fallback.

It's 99.9% combination of 2 bugs:

  1. Ugly proxy on client side, that breaks websocket packets in bad way.
  2. Faye does not catch this situation and can not do proper fallback to alternate protocol.

(2) is a real fuckup in our case, since we use faye for all client-server communications (no ajax at all).

@jcoglan
Copy link
Collaborator

jcoglan commented May 29, 2012

There's a bunch of ways a proxy can mess sockets up. I really need to take a look at the request you're seeing (method, URL, headers) before making a decision on how to handle it.

What I do know is that the Faye client should detect that WebSocket is not usable -- the server will not be establishing the connection properly -- and it ought to be able to detect this and use something else. Does this bug result in broken clients, or just log noise from the initial connection attempt?

@puzrin
Copy link

puzrin commented May 29, 2012

Yes, all his browsers, that started connection with websocket protocol, become broken. Those could not do automatic fallback to polling and others. May be, that's caused by another bug. Don't know exactly.

Here is a live log of all "ivalid token u" exceptions: http://fontello.com/fuckup.log . Fontello uses faye to broadcast "online" users & send click at 1 button to server. Very simple - almost no place to make errors.

Now wait a bit, until person, that managed to reproduce bug, will be back at work and can do some simple tests fontello/fontello#60 (comment)

If you need something more - feel free to ask anytime.

@puzrin
Copy link

puzrin commented May 30, 2012

Got more info. Seems, that's another bug. No messages in log, but man sent me screenshot with error from console.

Please, skip first error, it's our internal bug.

@ixti
Copy link

ixti commented May 30, 2012

@jcoglan I have added e.message to our logs. Here's some explanation of the fuckup logs on fontello:

  • url, headers, trailer, method - are coming directly from request argument.
  • remote - is a remoteAddress of request's socket.
  • params - is params argument as is.
  • data - is an untouched data received by collecting together data events.

You can see the patch we use to produce these logs here: https://gist.github.com/2829288

@jcoglan
Copy link
Collaborator

jcoglan commented Jun 5, 2012

Am reading the fuckup logs. Here are some things that are going wrong:

url:      /faye/0zmhsbl1ws3f151jqq8my05u8wbq
headers:  
  user-agent:      Opera/9.80 (Windows NT 6.1; WOW64; U; en) Presto/2.10.229 Version/11.64
  host:            fontello.com
  accept:          text/html, application/xml;q=0.9, application/xhtml+xml, image/png, image/webp, image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1
  accept-language: en,pl-PL;q=0.9,pl;q=0.8
  accept-encoding: gzip, deflate
  cookie:          __utma=156769964.750283226.1336717343.1336717343.1337595753.2; __utmz=156769964.1336717343.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); phpbb2mysql_data=a%3A2%3A%7Bs%3A11%3A%22autologinid%22%3Bs%3A0%3A%22%22%3Bs%3A6%3A%22userid%22%3Bi%3A-1%3B%7D
  connection:      Keep-Alive
params:   

trailers: 

method:   GET
data:     undefined
remote:   193.104.184.225

You can tell from the client ID in the URL that this is an EventSource request. However, EventSource requests are supposed to contain text/event-stream in the Accept header, so this request is bad.

url:      /faye
headers:  
  host:            fontello.com
  connection:      keep-alive
  user-agent:      Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_4) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.52 Safari/536.5
  accept:          text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  accept-encoding: gzip,deflate,sdch
  accept-language: en-US,en;q=0.8
  accept-charset:  ISO-8859-1,utf-8;q=0.7,*;q=0.3
  cookie:          __utma=156769964.1879399232.1338320669.1338320669.1338320669.1; __utmc=156769964; __utmz=156769964.1338320669.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)
params:   

trailers: 

method:   GET
data:     undefined
remote:   63.203.180.99

This is a GET request with no query string, and nothing to indicate it's a WebSocket or EventSource connection. It's simply invalid; there is nothing useful the Faye server can do with this. It actually seems unlikely that the request was made by a Faye client at all, or if it was then it's been messed up by a proxy and there's not a lot we can do with it.

url:      /faye
headers:  
  connection:            Keep-Alive
  host:                  fontello.com
  accept:                text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  accept-language:       en-us,en;q=0.5
  accept-encoding:       gzip, deflate
  user-agent:            Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:13.0) Gecko/20100101 Firefox/13.0
  cookie:                __utma=156769964.407947976.1338335337.1338335337.1338335337.1; __utmb=156769964.2.9.1338335341035; __utmc=156769964; __utmz=156769964.1338335337.1.1.utmcsr=nodeca.github.com|utmccn=(referral)|utmcmd=referral|utmcct=/fontomas/
  pragma:                no-cache
  cache-control:         no-cache
  origin:                http://fontello.com
  sec-websocket-key:     vO1umqPPiBmKAziYKzk22g==
  sec-websocket-version: 13
params:   

trailers: 

method:   GET
data:     undefined
remote:   180.194.238.4

This is a WebSocket request (notice Sec-WebSocket-*) but its Connection header is wrong, and it has no Upgrade header, so it's getting handled as normal HTTP. We could conceivably still treat this as a WebSocket connection although I doubt that whatever proxy is messing the request up will be able to handle the WebSocket response without doing the same.

url:      /faye
headers:  
  user-agent:                Opera/9.80 (Windows NT 6.1; WOW64; U; en) Presto/2.10.229 Version/11.64
  host:                      fontello.com
  accept:                    text/html, application/xml;q=0.9, application/xhtml+xml, image/png, image/webp, image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1
  accept-language:           en,pl-PL;q=0.9,pl;q=0.8
  accept-encoding:           gzip, deflate
  referer:                   http://fontello.com/
  cookie:                    __utma=156769964.750283226.1336717343.1336717343.1337595753.2; __utmz=156769964.1336717343.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); phpbb2mysql_data=a%3A2%3A%7Bs%3A11%3A%22autologinid%22%3Bs%3A0%3A%22%22%3Bs%3A6%3A%22userid%22%3Bi%3A-1%3B%7D
  connection:                Keep-Alive
  content-length:            113
  content-transfer-encoding: binary
params:   
  [{"channel":"/meta/connect","clientId":"0zmhsbl1ws3f151jqq8my05u8wbq","connectionType":"eventsource","id":"6w9"}]: 
trailers: 

method:   POST
data:     [{"channel":"/meta/connect","clientId":"0zmhsbl1ws3f151jqq8my05u8wbq","connectionType":"eventsource","id":"6w9"}]
remote:   193.104.184.225

This is a POST containing JSON that should have Content-Type: application/json, but it does not, so it's being treated as application/x-www-form-urlencoded. The body in this case should be:

message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22clientId%22%3A%220zmhsbl1ws3f151jqq8my05u8wbq%22%2C%22connectionType%22%3A%22eventsource%22%2C%22id%22%3A%226w9%22%7D%5D

This could potentially be fixed by trying to parse the body as a query string, then if that fails treat the body as literal JSON. This feels messy though, and likely to have other unwanted side effects.

The failure of this request could also explain the inability to fall back after broken WebSockets, since it means that long-polling will not work either.

On the whole it seems that either your hosting stack, or proxies being used by your users, are breaking almost all the transports used by Faye. The only one that will probably work is callback-polling, so in some cases the client will not be able to connect at all if the Faye server is on the same origin as the page.

One final piece of research I'd like you to do is to check whether we can detect failed WebSocket and EventSource connections. Take a look at https://github.com/faye/faye/blob/master/javascript/transport/web_socket.js and https://github.com/faye/faye/blob/master/javascript/transport/event_source.js, and look for the creation of socket objects. Add onopen, onerror and onclose handers (or modify the existing ones) to find out, on browsers with broken Faye connections:

  • Which events out of onopen, onerror, onclose fire?
  • What order to they fire in?
  • How long is it before you can an error/close event, if any?

@jcoglan
Copy link
Collaborator

jcoglan commented Jul 15, 2012

What's the status of this issue? I've not heard any updates in a month.

@puzrin
Copy link

puzrin commented Jul 15, 2012

At our side status with websocket->polling fallback did not changed. Just started to work with backlog tasks yesterdy.

James, i offer to close this one now, as partially solved (about bad/unclear logs). When we get more info about clientside - me or ixti will create new ticket with better description.

@jcoglan
Copy link
Collaborator

jcoglan commented Aug 2, 2012

I'm closing this per @puzrin's last comment. Please open a new issue if/when you have more concrete information.

@jcoglan jcoglan closed this as completed Aug 2, 2012
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants