search

postwait / node-amqp

[UNMAINTAINED] node-amqp is an AMQP client for nodejs
MIT License
1.69k stars 357 forks source link

Unhandled connection error: COMMAND_INVALID - second 'channel.open' seen #157

Open lookfirst opened 11 years ago

lookfirst commented 11 years ago

Save this to foo.coffee and run coffee foo.coffee...

amqp = require('amqp')
amqp.createConnection "YOUR CONNECTION URL", {}, (connection) ->
    connection.exchange 'ldexchange', {type: 'direct', confirm: true, durable: true}, (exchange) ->

It outputs the error that is the subject of this issue. Any idea why?

Using the connection.on 'ready' works fine for me, but I really need to make sure that this stuff is all setup before my app tries to to send messages, so I'd rather use callbacks to set everything up.

zeisss commented 11 years ago

I had to change your code a bit, but this works for me:

amqp = require('amqp')
amqp.createConnection {url: "amqp://guest:guest@localhost:5672"}, (connection) ->
    connection.exchange 'ldexchange', {type: 'direct', confirm: true, durable: true}, (exchange) ->

I received an error with your parameters to createConnection, but I have no idea if this is the error you see:

TypeError: Object.getOwnPropertyNames called on non-object
    at Function.getOwnPropertyNames (native)
    at mixin (..../node-amqp/amqp.js:39:14)
    at Connection.setOptions (..../node-amqp/amqp.js:1020:3)
    at new Connection (..../node-amqp/amqp.js:798:8)
    at Object.exports.createConnection (..../node-amqp/amqp.js:1010:11)
    at Object.<anonymous> (..../node-amqp/foo.coffee:6:8)
    at Object.<anonymous> (..../node-amqp/foo.coffee:14:4)
    at Module._compile (module.js:449:26)
    at Object.exports.run (..../node_modules/coffee-script/lib/coffee-script/coffee-script.js:83:25)
    at compileScript (..../node_modules/coffee-script/lib/coffee-script/command.js:177:29)

Did this help?

TheDeveloper commented 10 years ago

I'm seeing this problem too.

It appears to happen when you try to declare an exchange in the same tick of the event loop as the readyCallback is called.

This is the debug output I get when running into this issue:

making non-ssl connection
setting connection timeout to 10000
Initiating handshake...
connected so resetting connection timeout
execute: 0100000000014a000a000a0009000001250c6361706162696c69746965734600000058127075626c69736865725f636f6e6669726d7374011a65786368616e67655f65786368616e67655f62696e64696e677374010a62617369632e6e61636b740116636f6e73756d65725f63616e63656c5f6e6f74696679740109636f707972696768745300000027436f707972696768742028432920323030372d3230313320476f5069766f74616c2c20496e632e0b696e666f726d6174696f6e53000000354c6963656e73656420756e64657220746865204d504c2e202053656520687474703a2f2f7777772e7261626269746d712e636f6d2f08706c6174666f726d530000000a45726c616e672f4f54500770726f6475637453000000085261626269744d510776657273696f6e5300000005332e312e350000000e414d51504c41494e20504c41494e00000005656e5f5553ce
Executing method 0 { name: 'connectionStart',
  fields:
   [ { name: 'versionMajor', domain: 'octet' },
     { name: 'versionMinor', domain: 'octet' },
     { name: 'serverProperties', domain: 'table' },
     { name: 'mechanisms', domain: 'longstr' },
     { name: 'locales', domain: 'longstr' } ],
  methodIndex: 10,
  classIndex: 10 } { versionMajor: 0,
  versionMinor: 9,
  serverProperties:
   { capabilities:
      { publisher_confirms: true,
        exchange_exchange_bindings: true,
        'basic.nack': true,
        consumer_cancel_notify: true },
     copyright: 'Copyright (C) 2007-2013 GoPivotal, Inc.',
     information: 'Licensed under the MPL.  See http://www.rabbitmq.com/',
     platform: 'Erlang/OTP',
     product: 'RabbitMQ',
     version: '3.1.5' },
  mechanisms: 'AMQPLAIN PLAIN',
  locales: 'en_US' }
0 > connectionStart {"versionMajor":0,"versionMinor":9,"serverProperties":{"capabilities":{"publisher_confirms":true,"exchange_exchange_bindings":true,"basic.nack":true,"consumer_cancel_notify":true},"copyright":"Copyright (C) 2007-2013 GoPivotal, Inc.","information":"Licensed under the MPL.  See http://www.rabbitmq.com/","platform":"Erlang/OTP","product":"RabbitMQ","version":"3.1.5"},"mechanisms":"AMQPLAIN PLAIN","locales":"en_US"}
0 < connectionStartOk {"clientProperties":{"version":"0.2.0","platform":"node-v0.10.26","product":"node-amqp"},"mechanism":"AMQPLAIN","response":{"LOGIN":"guest","PASSWORD":"guest"},"locale":"en_US"}
sending frame: 1,0,0,0,0,0,129,0,10,0,11,0,0,0,67,7,118,101,114,115,105,111,110,83,0,0,0,5,48,46,50,46,48,8,112,108,97,116,102,111,114,109,83,0,0,0,13,110,111,100,101,45,118,48,46,49,48,46,50,54,7,112,114,111,100,117,99,116,83,0,0,0,9,110,111,100,101,45,97,109,113,112,8,65,77,81,80,76,65,73,78,0,0,0,35,5,76,79,71,73,78,83,0,0,0,5,103,117,101,115,116,8,80,65,83,83,87,79,82,68,83,0,0,0,5,103,117,101,115,116,5,101,110,95,85,83,206
execute: 0100000000000c000a001e0000000200000258ce
Executing method 0 { name: 'connectionTune',
  fields:
   [ { name: 'channelMax', domain: 'short' },
     { name: 'frameMax', domain: 'long' },
     { name: 'heartbeat', domain: 'short' } ],
  methodIndex: 30,
  classIndex: 10 } { channelMax: 0, frameMax: 131072, heartbeat: 600 }
0 > connectionTune {"channelMax":0,"frameMax":131072,"heartbeat":600}
tweaking maxFrameBuffer to 131072
0 < connectionTuneOk {"channelMax":0,"frameMax":131072,"heartbeat":0}
sending frame: 1,0,0,0,0,0,12,0,10,0,31,0,0,0,2,0,0,0,0,206
0 < connectionOpen {"virtualHost":"/","reserved1":"","reserved2":true}
sending frame: 1,0,0,0,0,0,8,0,10,0,40,1,47,0,1,206
execute: 01000000000005000a002900ce
Executing method 0 { name: 'connectionOpenOk',
  fields: [ { name: 'reserved1', domain: 'shortstr' } ],
  methodIndex: 41,
  classIndex: 10 } { reserved1: '' }
0 > connectionOpenOk {"reserved1":""}
1 < channelOpen {"reserved1":""}
sending frame: 1,0,1,0,0,0,5,0,20,0,10,0,206
2 < channelOpen {"reserved1":""}
sending frame: 1,0,2,0,0,0,5,0,20,0,10,0,206
1 < channelOpen {"reserved1":""}
sending frame: 1,0,1,0,0,0,5,0,20,0,10,0,206
2 < channelOpen {"reserved1":""}
sending frame: 1,0,2,0,0,0,5,0,20,0,10,0,206
3 < channelOpen {"reserved1":""}
sending frame: 1,0,3,0,0,0,5,0,20,0,10,0,206
4 < channelOpen {"reserved1":""}
sending frame: 1,0,4,0,0,0,5,0,20,0,10,0,206
execute: 010001000000080014000b00000000ce010002000000080014000b00000000ce01000000000037000a003201f72c434f4d4d414e445f494e56414c4944202d207365636f6e6420276368616e6e656c2e6f70656e27207365656e0014000ace
Executing method 1 { name: 'channelOpenOk',
  fields: [ { name: 'reserved1', domain: 'longstr' } ],
  methodIndex: 11,
  classIndex: 20 } { reserved1: '' }
1 > channelOpenOk {"reserved1":""}
1 < exchangeDeclare {"reserved1":0,"reserved2":false,"reserved3":false,"exchange":"counters","type":"topic","passive":false,"durable":true,"autoDelete":false,"internal":false,"noWait":false,"arguments":{}}
sending frame: 1,0,1,0,0,0,26,0,40,0,10,0,0,8,99,111,117,110,116,101,114,115,5,116,111,112,105,99,2,0,0,0,0,206
Executing method 2 { name: 'channelOpenOk',
  fields: [ { name: 'reserved1', domain: 'longstr' } ],
  methodIndex: 11,
  classIndex: 20 } { reserved1: '' }
2 > channelOpenOk {"reserved1":""}
2 < exchangeDeclare {"reserved1":0,"reserved2":false,"reserved3":false,"exchange":"pageview","type":"topic","passive":false,"durable":true,"autoDelete":false,"internal":false,"noWait":false,"arguments":{}}
sending frame: 1,0,2,0,0,0,26,0,40,0,10,0,0,8,112,97,103,101,118,105,101,119,5,116,111,112,105,99,2,0,0,0,0,206
Executing method 0 { name: 'connectionClose',
  fields:
   [ { name: 'replyCode', domain: 'short' },
     { name: 'replyText', domain: 'shortstr' },
     { name: 'classId', domain: 'short' },
     { name: 'methodId', domain: 'short' } ],
  methodIndex: 50,
  classIndex: 10 } { replyCode: 503,
  replyText: 'COMMAND_INVALID - second \'channel.open\' seen',
  classId: 20,
  methodId: 10 }
0 > connectionClose {"replyCode":503,"replyText":"COMMAND_INVALID - second 'channel.open' seen","classId":20,"methodId":10}
error: amqp error code=503

For the time being I've worked around this by wrapping code in the ready callback in a setImmediate(). It seems running on the next tick helps avoid the issue. Here's the debug output for that:

making non-ssl connection
setting connection timeout to 10000
Initiating handshake...
connected so resetting connection timeout
execute: 0100000000014a000a000a0009000001250c6361706162696c69746965734600000058127075626c69736865725f636f6e6669726d7374011a65786368616e67655f65786368616e67655f62696e64696e677374010a62617369632e6e61636b740116636f6e73756d65725f63616e63656c5f6e6f74696679740109636f707972696768745300000027436f707972696768742028432920323030372d3230313320476f5069766f74616c2c20496e632e0b696e666f726d6174696f6e53000000354c6963656e73656420756e64657220746865204d504c2e202053656520687474703a2f2f7777772e7261626269746d712e636f6d2f08706c6174666f726d530000000a45726c616e672f4f54500770726f6475637453000000085261626269744d510776657273696f6e5300000005332e312e350000000e414d51504c41494e20504c41494e00000005656e5f5553ce
Executing method 0 { name: 'connectionStart',
  fields:
   [ { name: 'versionMajor', domain: 'octet' },
     { name: 'versionMinor', domain: 'octet' },
     { name: 'serverProperties', domain: 'table' },
     { name: 'mechanisms', domain: 'longstr' },
     { name: 'locales', domain: 'longstr' } ],
  methodIndex: 10,
  classIndex: 10 } { versionMajor: 0,
  versionMinor: 9,
  serverProperties:
   { capabilities:
      { publisher_confirms: true,
        exchange_exchange_bindings: true,
        'basic.nack': true,
        consumer_cancel_notify: true },
     copyright: 'Copyright (C) 2007-2013 GoPivotal, Inc.',
     information: 'Licensed under the MPL.  See http://www.rabbitmq.com/',
     platform: 'Erlang/OTP',
     product: 'RabbitMQ',
     version: '3.1.5' },
  mechanisms: 'AMQPLAIN PLAIN',
  locales: 'en_US' }
0 > connectionStart {"versionMajor":0,"versionMinor":9,"serverProperties":{"capabilities":{"publisher_confirms":true,"exchange_exchange_bindings":true,"basic.nack":true,"consumer_cancel_notify":true},"copyright":"Copyright (C) 2007-2013 GoPivotal, Inc.","information":"Licensed under the MPL.  See http://www.rabbitmq.com/","platform":"Erlang/OTP","product":"RabbitMQ","version":"3.1.5"},"mechanisms":"AMQPLAIN PLAIN","locales":"en_US"}
0 < connectionStartOk {"clientProperties":{"version":"0.2.0","platform":"node-v0.10.26","product":"node-amqp"},"mechanism":"AMQPLAIN","response":{"LOGIN":"guest","PASSWORD":"guest"},"locale":"en_US"}
sending frame: 1,0,0,0,0,0,129,0,10,0,11,0,0,0,67,7,118,101,114,115,105,111,110,83,0,0,0,5,48,46,50,46,48,8,112,108,97,116,102,111,114,109,83,0,0,0,13,110,111,100,101,45,118,48,46,49,48,46,50,54,7,112,114,111,100,117,99,116,83,0,0,0,9,110,111,100,101,45,97,109,113,112,8,65,77,81,80,76,65,73,78,0,0,0,35,5,76,79,71,73,78,83,0,0,0,5,103,117,101,115,116,8,80,65,83,83,87,79,82,68,83,0,0,0,5,103,117,101,115,116,5,101,110,95,85,83,206
execute: 0100000000000c000a001e0000000200000258ce
Executing method 0 { name: 'connectionTune',
  fields:
   [ { name: 'channelMax', domain: 'short' },
     { name: 'frameMax', domain: 'long' },
     { name: 'heartbeat', domain: 'short' } ],
  methodIndex: 30,
  classIndex: 10 } { channelMax: 0, frameMax: 131072, heartbeat: 600 }
0 > connectionTune {"channelMax":0,"frameMax":131072,"heartbeat":600}
tweaking maxFrameBuffer to 131072
0 < connectionTuneOk {"channelMax":0,"frameMax":131072,"heartbeat":0}
sending frame: 1,0,0,0,0,0,12,0,10,0,31,0,0,0,2,0,0,0,0,206
0 < connectionOpen {"virtualHost":"/","reserved1":"","reserved2":true}
sending frame: 1,0,0,0,0,0,8,0,10,0,40,1,47,0,1,206
execute: 01000000000005000a002900ce
Executing method 0 { name: 'connectionOpenOk',
  fields: [ { name: 'reserved1', domain: 'shortstr' } ],
  methodIndex: 41,
  classIndex: 10 } { reserved1: '' }
0 > connectionOpenOk {"reserved1":""}
1 < channelOpen {"reserved1":""}
sending frame: 1,0,1,0,0,0,5,0,20,0,10,0,206
2 < channelOpen {"reserved1":""}
sending frame: 1,0,2,0,0,0,5,0,20,0,10,0,206
execute: 010001000000080014000b00000000ce
Executing method 1 { name: 'channelOpenOk',
  fields: [ { name: 'reserved1', domain: 'longstr' } ],
  methodIndex: 11,
  classIndex: 20 } { reserved1: '' }
1 > channelOpenOk {"reserved1":""}
1 < exchangeDeclare {"reserved1":0,"reserved2":false,"reserved3":false,"exchange":"counters","type":"topic","passive":false,"durable":true,"autoDelete":false,"internal":false,"noWait":false,"arguments":{}}
sending frame: 1,0,1,0,0,0,26,0,40,0,10,0,0,8,99,111,117,110,116,101,114,115,5,116,111,112,105,99,2,0,0,0,0,206
execute: 010002000000080014000b00000000ce
Executing method 2 { name: 'channelOpenOk',
  fields: [ { name: 'reserved1', domain: 'longstr' } ],
  methodIndex: 11,
  classIndex: 20 } { reserved1: '' }
2 > channelOpenOk {"reserved1":""}
2 < exchangeDeclare {"reserved1":0,"reserved2":false,"reserved3":false,"exchange":"pageview","type":"topic","passive":false,"durable":true,"autoDelete":false,"internal":false,"noWait":false,"arguments":{}}
sending frame: 1,0,2,0,0,0,26,0,40,0,10,0,0,8,112,97,103,101,118,105,101,119,5,116,111,112,105,99,2,0,0,0,0,206
execute: 010001000000040028000bce
Executing method 1 { name: 'exchangeDeclareOk',
  fields: [],
  methodIndex: 11,
  classIndex: 40 } {}
1 > exchangeDeclareOk {}
execute: 010002000000040028000bce
Executing method 2 { name: 'exchangeDeclareOk',
  fields: [],
  methodIndex: 11,
  classIndex: 40 } {}
2 > exchangeDeclareOk {}
matomesc commented 10 years ago

I ran into this issue when calling connection.publish several times in the same tick of the event loop. Solved it by using process.setImmediate.