Warning from spymemcached

[Siddharth Jagtiani]

Hi,

I am using spymemcached as client. I run memcached on ubuntu. ps -ef returns the following

 "root      6669 14126  0 11:44 pts/2    00:00:00 /usr/bin/memcached -m 64 -U 11211 -p 11211 -u root -l localhost"

I keep getting this annoying message, and not much found after googleing around. Please help.

2012-02-06 14:06:14.106 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@1d439fe

2012-02-06 14:06:14.107 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

java.net.ConnectException: Connection refused

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:313)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:199)

at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1622)

Regards

Siddharth

[Dustin]

You're trying hard to run it as root.  You should not do that.

The annoying message is "connection refused."  You don't have the server bound to the interface you're trying to connect to.  If you are forcing a bind on 127.0.0.1, you should connect to 127.0.0.1.

[Siddharth Jagtiani]

Thanks for your prompt response.

I have modified my memcached load to "/usr/bin/memcached -m 64 -U 11211 -p 11211 -u root -l 127.0.0.1"

Client now uses "super(new InetSocketAddress("127.0.0.1", 11211));"

On the server I ran ps -ef

prompt>:~$ sudo ps -ef | grep memcached

[sudo] password for username: 

username  26614 14126  0 09:34 pts/2    00:00:00 /usr/bin/memcached -m 64 -U 11211 -p 11211 -u root -l 127.0.0.1

Also

prompt$ sudo netstat -anp | grep 11211

tcp        0      0 127.0.0.1:11211         0.0.0.0:*               LISTEN      26614/memcached 

tcp        0      0 127.0.0.1:11211         127.0.0.1:56746         ESTABLISHED 26614/memcached 

tcp6       0      0 127.0.0.1:56746         127.0.0.1:11211         ESTABLISHED 26625/java      

udp        0      0 127.0.0.1:11211         0.0.0.0:*                           26614/memcached 

I obvious still get the warn message. I know I am missing something really basic here.

A flip question : Does this have any side effect ? Performance, CPU util or anything else ? If not, is there a log4j setting ?

Thanks again

Siddharth

[Siddharth Jagtiani]

2012-02-06 14:06:14.106 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@1d439fe

2012-02-06 14:06:14.107 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

java.net.ConnectException: Connection refused

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:313)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:199)

at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1622)

[Dustin]

The error says you're trying to connect to 0.0.0.0.  Just look at the log message.  This makes no sense as a destination address and doesn't match what you're saying.

[Dustin]

And honestly... don't run it as root.  It doesn't complain because we thought it'd be fun for you to write "-u root" -- it complains because it's a bad idea.

[Siddharth Jagtiani]

So is there a way to fix the annoying message or a way to mask it. Since it obviously has no impact on my setup and functionality.

Siddharth

[Dustin]

On Tuesday, February 7, 2012 7:59:32 PM UTC-8, Siddharth Jagtiani wrote:

So is there a way to fix the annoying message or a way to mask it. Since it obviously has no impact on my setup and functionality.

  Do you honestly believe that not being able to connect to the server you've configured it to talk to has no impact on your setup and/or functionality?

  If you want it to stop giving you that error, you should not configure it to connect there.  I don't know how you think you're connecting, but I have a hard time imagining the client just made up that address, tried to connect to it, and complained when it couldn't.  Can you post your actual connection code, at least?

  I'd also strongly recommend you not run the server as root.  That's still not a good idea.

[Siddharth Jagtiani]

Dustin,

I immediately responded about "not running as root" and "client piece of code", as soon as I saw your first response. I guessed you missed seeing my response (here it is below again). Also you seem to respond without "original message thread" so we keep loosing the responses :).

Thanks again for your patience on this.

Siddharth

I have modified my memcached load to "/usr/bin/memcached -m 64 -U 11211 -p 11211 -u root -l 127.0.0.1"

Client class extends from spy memcachedclientnow and uses "super(new InetSocketAddress("127.0.0.1", 11211));"

On the server I ran ps -ef

prompt>:~$ sudo ps -ef | grep memcached

[sudo] password for username: 

username  26614 14126  0 09:34 pts/2    00:00:00 /usr/bin/memcached -m 64 -U 11211 -p 11211 -u root -l 127.0.0.1

Also

prompt$ sudo netstat -anp | grep 11211

tcp        0      0 127.0.0.1:11211         0.0.0.0:*               LISTEN      26614/memcached 

tcp        0      0 127.0.0.1:11211         127.0.0.1:56746         ESTABLISHED 26614/memcached 

tcp6       0      0 127.0.0.1:56746         127.0.0.1:11211         ESTABLISHED 26625/java      

udp        0      0 127.0.0.1:11211         0.0.0.0:*                           26614/memcached 

I obvious still get the warn message. I know I am missing something really basic here.

A flip question : Does this have any side effect ? Performance, CPU util or anything else ? If not, is there a log4j setting ?

2012-02-06 14:06:14.106 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@1d439fe

2012-02-06 14:06:14.107 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

java.net.ConnectException: Connection refused

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:313)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:199)

at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1622)

Thanks again

Siddharth

[Dustin]

On Wednesday, February 8, 2012 12:29:00 AM UTC-8, Siddharth Jagtiani wrote:

 

I immediately responded about "not running as root"

  I see no response about not running as root.  It works, but you're not justifying it and you're still doing it.  It's generally something you never want to do, but it's not the actual cause of the problem you're having.  Not understanding everything you're doing does make it harder to understand your pboelm, though.

 

and "client piece of code", as soon as I saw your first response. I guessed you missed seeing my response (here it is below again).

  I read your response, and it's still in the archive.  You don't need to keep posting it.

 

Also you seem to respond without "original message thread" so we keep loosing the responses :).

  This is all in the same thread on google groups.  I don't know what you're referring to, but you're being hard to follow.

  If you don't understand my response, state, specifically, what you don't understand about it.  As it is, the client is telling you that there's a fatal error connecting to the server you've defined, and you're calling the log message annoying and wondering how to disable it.  Just disable the client altogether if you believe not being able to connect to a server doesn't affect your service, but you don't want to read the log messages about it.  You'll still not be connected, but it won't be logging.

[Siddharth Jagtiani]

Ok, let me make this easier to follow.

I run the server on my localhost with this command

prompt>:~$ /usr/bin/memcached -m 64 -U 11211 -p 11211 -l 127.0.0.1

I kinda did not remove the "-u root", silly me. I got it.

ps -ef | grep memcached shows

username  12029  2961  0 13:32 pts/2    00:00:00 /usr/bin/memcached -m 64 -U 11211 -p 11211 -l 127.0.0.1

sudo netstat -anp | grep 11211 shows

prompt>:~$ sudo netstat -anp | grep 11211

tcp        0      0 127.0.0.1:11211         0.0.0.0:*               LISTEN      12029/memcached 

tcp        0      0 127.0.0.1:11211         127.0.0.1:36642         ESTABLISHED 12029/memcached 

tcp6       0      0 127.0.0.1:36642         127.0.0.1:11211         ESTABLISHED 13941/java      

udp        0      0 127.0.0.1:11211         0.0.0.0:*                           12029/memcached 

unix  2      [ ACC ]     STREAM     LISTENING     11211    1821/dbus-daemon    @/tmp/dbus-TelpJZAoJl

Now, I use spymemcached as my client, and use it like this

private MyClass() throws UnknownHostException, IOException {

super(new InetSocketAddress("127.0.0.1", 11211));

}

Results

I am able to set/get with no issues at all. My cache populates and work perfectly well.

But every 20 seconds I get the below warning message. I call this annoying (forgive my expression here, I dont mean to offend anyone), since everything works. And this WARN/INFO message carries no function issue for me.

2012-02-09 13:55:59.322 INFO net.spy.memcached.MemcachedConnection:  Reconnecting {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

2012-02-09 13:55:59.323 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@15f0688

2012-02-09 13:55:59.323 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

java.net.ConnectException: Connection refused

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:313)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:199)

at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1622)

2012-02-09 13:55:59.324 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=0.0.0.0/0.0.0.0:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 26.

Regards

Siddharth

[Dustin]

On Thursday, February 9, 2012 12:33:17 AM UTC-8, Siddharth Jagtiani wrote:

Now, I use spymemcached as my client, and use it like this

private MyClass() throws UnknownHostException, IOException {

super(new InetSocketAddress("127.0.0.1", 11211));

}

This is not a complete example that demonstrates the problem. 

[Siddharth Jagtiani]

I have shared all that is until I initialize the server and client. Would you like a set/get calls too ? Or would you like a test program that simulates this ?

Siddharth

[Dustin]

On Thursday, February 9, 2012 11:13:46 PM UTC-8, Siddharth Jagtiani wrote:

I have shared all that is until I initialize the server and client. Would you like a set/get calls too ? Or would you like a test program that simulates this ?

  I would like a complete example that demonstrates the problem.  I can only imagine what you're doing with what you've shared.  It'd be easier if I could just see it.

[Siddharth Jagtiani]

Figured it out. I now run 

 /usr/bin/memcached -m 64 -U 11211 -p 11211

instead of

 /usr/bin/memcached -m 64 -U 11211 -p 11211 -l 127.0.0.1

And I dont get those warning messages anymore.

[Dustin]

On Friday, February 10, 2012 5:46:14 PM UTC-8, Siddharth Jagtiani wrote:

Figured it out. I now run 

 /usr/bin/memcached -m 64 -U 11211 -p 11211

instead of

 /usr/bin/memcached -m 64 -U 11211 -p 11211 -l 127.0.0.1

And I dont get those warning messages anymore.

 This doesn't solve the problem of you connecting to something to something you don't think you're trying to connect to.  It just makes the thing you think you're not doing work.

[MCON Dev]

My memcached set's are passing, get's are passing and telnet stats reports get hits, also memory used. So I dont see a issue here.

[Dustin]

On Friday, February 10, 2012 9:21:22 PM UTC-8, mCon Dev Team wrote:

My memcached set's are passing, get's are passing and telnet stats reports get hits, also memory used. So I dont see a issue here.

  That's fine.  It's not doing what you think it's doing, and you don't understand why changing the binding away from forced localhost will fix your client that was supposed to be connecting to localhost from attempting to connect to a different address and complaining that it was unable to do so.  I expect that without fixing and understanding your problem, you will experience new and exciting failures in the future.

  When you come back, please bring a small sample bit of code that demonstrates your problem.

[Siddharth Jagtiani]

Sure, I'll try to reproduce it with some sample code and share it. A few days, as of now I need to get to some perf :)

Siddharth

[U.S. Adha]

Hi Dustin

             This is Umashankar. I am trying to put 60 million object into memcached. I am having memcached 1.4.7 version. I have sufficient RAM to put object as I have assign 14GB to my memcached. but once I am trying to put objects it showing me following message 

First these :

2012-08-01 14:05:14.959 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@6fc5f743 has 1, interested in 5

2012-08-01 14:05:17.405 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@6fc5f743 has a ready op, handling IO

2012-08-01 14:05:17.662 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has 5, interested in 5

2012-08-01 14:05:17.662 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has a ready op, handling IO

2012-08-01 14:05:17.663 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has 5, interested in 5

2012-08-01 14:05:17.663 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has a ready op, handling IO

2012-08-01 14:05:17.664 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has 5, interested in 5

2012-08-01 14:05:17.665 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has a ready op, handling IO

2012-08-01 14:05:17.665 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has 5, interested in 5

2012-08-01 14:05:17.665 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has a ready op, handling IO

2012-08-01 14:05:17.666 INFO net.spy.memcached.MemcachedConnection:  sun.nio.ch.SelectionKeyImpl@2d5253d5 has 5, interested in 5

Then  blow this exception :

java.lang.IllegalStateException: Timed out waiting to add Cmd: set Key: ECO-MAIL-CACHE:1d41402abc4b2a76b9719d9219828753875 Flags: 1 Exp: 0 Data Length: 394(max wait=10000ms)

        at net.spy.memcached.protocol.TCPMemcachedNodeImpl.addOp(TCPMemcachedNodeImpl.java:346)

        at net.spy.memcached.MemcachedConnection.addOperation(MemcachedConnection.java:697)

        at net.spy.memcached.MemcachedConnection.addOperation(MemcachedConnection.java:677)

        at net.spy.memcached.MemcachedConnection.enqueueOperation(MemcachedConnection.java:639)

        at net.spy.memcached.MemcachedClient.asyncStore(MemcachedClient.java:296)

        at net.spy.memcached.MemcachedClient.set(MemcachedClient.java:727)

        at com.ecomail.emx.core.cache.DefaultCache.set(DefaultCache.java:63)

        at com.ecomail.emx.exchange.db.SubscriptionCacheThread.createSubcriptionCache(SubscriptionCacheThread.java:88)

        at com.ecomail.emx.exchange.db.SubscriptionCacheThread.call(SubscriptionCacheThread.java:52)

        at com.ecomail.emx.exchange.db.SubscriptionCacheThread.call(SubscriptionCacheThread.java:22)

        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

        at java.util.concurrent.FutureTask.run(FutureTask.java:138)

        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

        at java.lang.Thread.run(Thread.java:662)

After putting  almost 2 million objects into memcached. 

Can you please suggest me, where am making mistake 

This is how am starting my memcached instance

memcached -m 14000 -l 192.168.10.242 -p 11211

[Matt Ingenthron]

You're likely overrunning the input queue.  If you configure it for a bit of blocking, it'll work better for you.  It's similar to the bulk loading description here:
http://www.couchbase.com/wiki/display/couchbase/Couchbase+Java+Client+Library

The tuning here is spymemcahed, just extended.

[Thushara Wijeratna]

When you don't specify -l option, memcached binds to all addresses on the machine, That 0.0.0.0 you see is really the INADDR_ANY constant used in sockets API.

Also, since the error is intermittent, it is not fatal. If it was, I suspect the re-connects would keep failing.

What is happening is that occasionally, spymemcached fails to connect, it retries and the retry works - hence your application is not aware of any issue.

It seems to be related to explicitly binding to the loopback interface. It would be nice if you could debug this further. Try to use -l with the IP of the machine and on the client code, change it to the same IP and see if the problem re-appears.

I bumped into this thread because I'm having connection re-connects with spymemcached too, version 2.5,