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.

Sign up for GitHub

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

Jump to bottom

Malformed response body from server: Unexpected token X with Comet on Node.js #59

Closed
mattheworiordan opened this issue Jun 28, 2015 · 3 comments
Closed

Malformed response body from server: Unexpected token X with Comet on Node.js #59

mattheworiordan opened this issue Jun 28, 2015 · 3 comments
Assignees
@paddybyers
Labels
bug Something isn't working. It's clear that this does need to be fixed.

Comments

@mattheworiordan
Copy link
Member

I have no idea how to inspect the actual traffic being sent from the Node.js app to and from a local realtime instance, however I keep seeing "Unexpected token [a letter]in the logs for every test I run when I force the use of the Comet transport withtransports: ['comet']`

 RUN_ONCE=true FREQUENCY=10 LOG_LEVEL=debug nodemon app.coffee
28 Jun 15:29:52 - [nodemon] v1.3.7
28 Jun 15:29:52 - [nodemon] to restart at any time, enter `rs`
28 Jun 15:29:52 - [nodemon] watching: *.*
28 Jun 15:29:52 - [nodemon] starting `coffee app.coffee`
2015-06-28T14:29:52.511Z - info: Liveness App created
2015-06-28T14:29:52.523Z - info: Starting set up
2015-06-28T14:29:52.571Z - info: Found the following apps: hG9k8g
2015-06-28T14:29:52.571Z - info: Found the following sites: eur01
2015-06-28T14:29:52.571Z - info: Setup complete
2015-06-28T14:29:52.826Z - debug: PublishCometAndHistory: service set up
2015-06-28T14:29:52.827Z - debug: PublishCometAndHistory: Started seq kzhaf5mvkju4n29 with 4 messages
Ably: Rest(): started
Ably: Auth(): anonymous, using basic auth
Ably: Realtime.ConnectionManager(): started
Ably: Connection.connect():
Ably: ConnectionManager.requestState(): requested state: connecting
Ably: ConnectionManager.cancelTransitionTimer():
Ably: ConnectionManager.enactStateChange: setting new state: connecting; reason = undefined
Ably: ConnectionManager.connectImpl(): starting connection
Ably: ConnectionManager.startTransitionTimer(): transitionState: [object Object]
Ably: ConnectionManager.chooseTransport():
Ably: ConnectionManager.chooseTransport(): Transport recovery mode = clean
Ably: CometTransport.connect(): starting
Ably: CometTransport.connect(): uri: https://local-rest.ably.io:443/comet/connect
Ably: CometTransport.connect(): connectParams:?key=hG9k8g.5BC1rQ%3AyzNeBJDVGA1QuAKa
Ably: NodeCometTransport.tryConnect(): viable transport NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=false; format=undefined; stream=true
Ably: ConnectionManager.setTransportPending(): transport = NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=false; format=undefined; stream=true
Ably: ConnectionManager.chooseTransport(): Establishing http transport: NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=false; format=undefined; stream=true
Ably: ConnectionManager.setTransportPending: on state = connected
Ably: ConnectionManager.activateTransport(): transport = NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=true; format=undefined; stream=true; connectionKey = h-n0EUYrWhch7xXn; connectionSerial = -1
Ably: ConnectionManager.notifyState(): new state: connected
Ably: ConnectionManager.cancelTransitionTimer():
Ably: ConnectionManager.enactStateChange: setting new state: connected; reason = undefined
2015-06-28T14:29:52.891Z - debug: PublishCometAndHistory: h-n0EUYrWh in eur01 connected
2015-06-28T14:29:52.891Z - debug: PublishCometAndHistory: All clients connected
2015-06-28T14:29:52.892Z - debug: PublishCometAndHistory: Publishing 4 messages on go32plm7r50tqpvi for connection h-n0EUYrWh in eur01
Ably: RealtimeChannel(): started; name = go32plm7r50tqpvi
Ably: Channel(): started; name = go32plm7r50tqpvi
2015-06-28T14:29:52.893Z - debug: PublishCometAndHistory: Publishing 1999 bytes to go32plm7r50tqpvi on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setPendingState: name = go32plm7r50tqpvi, state = attaching
2015-06-28T14:29:52.897Z - debug: PublishCometAndHistory: Publishing 1743 bytes to go32plm7r50tqpvi on h-n0EUYrWh in eur01
2015-06-28T14:29:52.898Z - debug: PublishCometAndHistory: Publishing 79 bytes to go32plm7r50tqpvi on h-n0EUYrWh in eur01
2015-06-28T14:29:52.898Z - debug: PublishCometAndHistory: Publishing 1935 bytes to go32plm7r50tqpvi on h-n0EUYrWh in eur01
2015-06-28T14:29:52.898Z - debug: PublishCometAndHistory: Publishing 4 messages on jyhg1e66xrh33di for connection h-n0EUYrWh in eur01
Ably: RealtimeChannel(): started; name = jyhg1e66xrh33di
Ably: Channel(): started; name = jyhg1e66xrh33di
2015-06-28T14:29:52.898Z - debug: PublishCometAndHistory: Publishing 479 bytes to jyhg1e66xrh33di on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setPendingState: name = jyhg1e66xrh33di, state = attaching
2015-06-28T14:29:52.899Z - debug: PublishCometAndHistory: Publishing 1439 bytes to jyhg1e66xrh33di on h-n0EUYrWh in eur01
2015-06-28T14:29:52.899Z - debug: PublishCometAndHistory: Publishing 399 bytes to jyhg1e66xrh33di on h-n0EUYrWh in eur01
2015-06-28T14:29:52.899Z - debug: PublishCometAndHistory: Publishing 285 bytes to jyhg1e66xrh33di on h-n0EUYrWh in eur01
2015-06-28T14:29:52.899Z - debug: PublishCometAndHistory: Publishing 4 messages on n2cazq5yxaymygb9 for connection h-n0EUYrWh in eur01
Ably: RealtimeChannel(): started; name = n2cazq5yxaymygb9
Ably: Channel(): started; name = n2cazq5yxaymygb9
2015-06-28T14:29:52.900Z - debug: PublishCometAndHistory: Publishing 1530 bytes to n2cazq5yxaymygb9 on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setPendingState: name = n2cazq5yxaymygb9, state = attaching
2015-06-28T14:29:52.900Z - debug: PublishCometAndHistory: Publishing 1519 bytes to n2cazq5yxaymygb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.900Z - debug: PublishCometAndHistory: Publishing 1279 bytes to n2cazq5yxaymygb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.900Z - debug: PublishCometAndHistory: Publishing 1663 bytes to n2cazq5yxaymygb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.900Z - debug: PublishCometAndHistory: Publishing 4 messages on pzd5hmfzvvdyrpb9 for connection h-n0EUYrWh in eur01
Ably: RealtimeChannel(): started; name = pzd5hmfzvvdyrpb9
Ably: Channel(): started; name = pzd5hmfzvvdyrpb9
2015-06-28T14:29:52.901Z - debug: PublishCometAndHistory: Publishing 239 bytes to pzd5hmfzvvdyrpb9 on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setPendingState: name = pzd5hmfzvvdyrpb9, state = attaching
2015-06-28T14:29:52.901Z - debug: PublishCometAndHistory: Publishing 879 bytes to pzd5hmfzvvdyrpb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.901Z - debug: PublishCometAndHistory: Publishing 495 bytes to pzd5hmfzvvdyrpb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.901Z - debug: PublishCometAndHistory: Publishing 255 bytes to pzd5hmfzvvdyrpb9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.901Z - debug: PublishCometAndHistory: Publishing 4 messages on vwqwdsc5wswnrk9 for connection h-n0EUYrWh in eur01
Ably: RealtimeChannel(): started; name = vwqwdsc5wswnrk9
Ably: Channel(): started; name = vwqwdsc5wswnrk9
2015-06-28T14:29:52.902Z - debug: PublishCometAndHistory: Publishing 1487 bytes to vwqwdsc5wswnrk9 on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setPendingState: name = vwqwdsc5wswnrk9, state = attaching
2015-06-28T14:29:52.902Z - debug: PublishCometAndHistory: Publishing 1485 bytes to vwqwdsc5wswnrk9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.902Z - debug: PublishCometAndHistory: Publishing 930 bytes to vwqwdsc5wswnrk9 on h-n0EUYrWh in eur01
2015-06-28T14:29:52.902Z - debug: PublishCometAndHistory: Publishing 1695 bytes to vwqwdsc5wswnrk9 on h-n0EUYrWh in eur01
Ably: RealtimeChannel.setAttached: activating channel; name = go32plm7r50tqpvi; message flags = undefined
Ably: NodeCometTransport.Request.readStream(): Malformed response body from server: Unexpected token m
Ably: RealtimeChannel.setAttached: activating channel; name = jyhg1e66xrh33di; message flags = undefined
Ably: RealtimeChannel.setAttached: activating channel; name = n2cazq5yxaymygb9; message flags = undefined
Ably: RealtimeChannel.setAttached: activating channel; name = pzd5hmfzvvdyrpb9; message flags = undefined
Ably: RealtimeChannel.setAttached: activating channel; name = vwqwdsc5wswnrk9; message flags = undefined
Ably: Realtime.close():
Ably: Connection.close(): connectionKey = h-n0EUYrWhch7xXn
Ably: ConnectionManager.requestState(): requested state: closing
Ably: ConnectionManager.cancelTransitionTimer():
Ably: ConnectionManager.enactStateChange: setting new state: closing; reason = undefined
2015-06-28T14:29:57.896Z - error: PublishCometAndHistory: Test kzhaf5mvkju4n29 failed: Could not publish & retrieve NaN messages from history within 5s
Ably: ConnectionManager.closeImpl(): closing connection
Ably: ConnectionManager.startTransitionTimer(): transitionState: [object Object]
Ably: ConnectionManager.closeImpl(): closing transport: null
Ably: ConnectionManager.closeImpl(): closing transport: NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=true; format=undefined; stream=true
Ably: ConnectionManager.closeImpl(): closing transport: NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=true; format=undefined; stream=true
Ably: CometTransport.close():
Ably: CometTransport.requestClose(): closing = true
Ably: ConnectionManager.setTransportPending: on state = closed
Ably: ConnectionManager.deactivateTransport(): transport = NodeCometTransport; uri=https://local-rest.ably.io:443/comet/; isConnected=true; format=undefined; stream=true
Ably: ConnectionManager.notifyState(): new state: closed
Ably: ConnectionManager.cancelTransitionTimer():
Ably: ConnectionManager.enactStateChange: setting new state: closed; reason = undefined
Ably: RealtimeChannel.setSuspended: deactivating channel; name = go32plm7r50tqpvi, err none
Ably: RealtimeChannel.failPendingMessages: channel; name = go32plm7r50tqpvi, err = undefined
Ably: RealtimeChannel.setSuspended: deactivating channel; name = jyhg1e66xrh33di, err none
Ably: RealtimeChannel.failPendingMessages: channel; name = jyhg1e66xrh33di, err = undefined
Ably: RealtimeChannel.setSuspended: deactivating channel; name = n2cazq5yxaymygb9, err none
Ably: RealtimeChannel.failPendingMessages: channel; name = n2cazq5yxaymygb9, err = undefined
Ably: RealtimeChannel.setSuspended: deactivating channel; name = pzd5hmfzvvdyrpb9, err none
Ably: RealtimeChannel.failPendingMessages: channel; name = pzd5hmfzvvdyrpb9, err = undefined
Ably: RealtimeChannel.setSuspended: deactivating channel; name = vwqwdsc5wswnrk9, err none
Ably: RealtimeChannel.failPendingMessages: channel; name = vwqwdsc5wswnrk9, err = undefined
Ably: CometTransport.dispose():
Ably: ConnectionManager.notifyState(): new state: closed
2015-06-28T14:29:57.899Z - debug: PublishCometAndHistory: Client h-n0EUYrWh in eur01 closed
@mattheworiordan mattheworiordan added the bug Something isn't working. It's clear that this does need to be fixed. label Jun 28, 2015
@paddybyers
Copy link
Member

Where's your code?

@paddybyers
Copy link
Member

Fixed: f09714e

@mattheworiordan
Copy link
Member Author

This seems to be fixed. I will close for now and re-open if it recurs. Clearly we need to bump the version though so that we can push the fix to npm

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@paddybyers paddybyers

Labels
bug Something isn't working. It's clear that this does need to be fixed.
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mattheworiordan @paddybyers