my mcrouter warmup can't work ,need help about mcrouter

[alikhtarov]

Hi, can you confirm you can only see this problem with warm server, and not with cold? Any potential network issues - can you verify that there are no issues connecting to the warm server manually? The errors show that mcrouter disconnected from the warm host due to some error, but not clear which from the log. Are there more lines before "AsyncSocket.cpp:729] AsyncSocket::close():"? At that point mcrouter is already force closing connection.

[lixiaoqiang-huoli]

i install mcrouter and memcached in one machine and i can use nc to connect the memcached .
in the log ,only warm server has this error . i noticed that when i use nc to connect the mcrouter and get a key, the TCP connection disconnect and reconnect,i don't know why mcrouter close connection and reconnect.

[lixiaoqiang-huoli]

i use centos 6.6 and memcache version is 1.4.22

[alikhtarov]

Were there any other lines before the first line "I0421 09:56:48.683130 9112 AsyncSocket.cpp:729]" ? The more complete log would help.

[alikhtarov]

Also please post the output of stats servers and stats suspect_servers commands sent to mcrouter when the issue is happening (you can simply use nc, i.e. echo stats servers | nc localhost <mcrouter_port>)

[lixiaoqiang-huoli]

before line is some thing like :
I0422 11:41:05.363095 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:41:05.363108 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:41:05.363129 22580 AsyncSocket.cpp:1332] AsyncSocket::handleWrite() this=0x7fa2d800c620, fd=24, state=1
I0422 11:41:05.363143 22580 AsyncSocket.cpp:1507] AsyncSocket::handleConnect() this=0x7fa2d800c620, fd=24, state=1
I0422 11:41:05.363160 22580 ProxyDestination.cpp:344] server 221.235.53.163:11212:TCP:ascii-100000 up (2 of 2)
I0422 11:41:05.363178 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d800c620, fd=24, evb=0x29b6d68, state=2, events=2
I0422 11:41:05.363242 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:41:05.363261 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:41:05.363314 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d800c620, fd=24, state=2
I0422 11:41:05.363373 22580 Fiber.cpp:112] Stack usage: 3588
I0422 11:41:05.363407 22580 Fiber.cpp:112] Stack usage: 5540
I0422 11:41:05.363422 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:41:05.363435 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:41:05.363482 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:41:05.363500 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:41:05.363620 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d800c620, fd=24, state=2
I0422 11:41:05.363653 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d800c620, fd=24, evb=0x29b6d68, state=2, events=0
I0422 11:41:05.363675 22580 AsyncSocket.cpp:729] AsyncSocket::close(): this=0x7fa2d800c620, fd_=24, state=2, shutdownFlags=0

the following is stats server and suspect_servers output
[root@kjwh163 lixq]# echo "stats servers" | nc 127.0.0.1 7001
I0422 11:45:54.106211 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:45:54.106271 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:45:54.106309 22580 AsyncSocket.cpp:211] new AsyncSocket(0x7fa2d8003840, evb=0x29b6d68, fd=12)
I0422 11:45:54.106353 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d8003840, fd=12, evb=0x29b6d68, state=2, events=2
I0422 11:45:54.106384 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:45:54.106397 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:45:54.106416 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d8003840, fd=12, state=2
STAT 221.235.53.163:11211:TCP:ascii-100000 avg_latency_us:1643.000 pending_reqs:0 inflight_reqs:0 closed:1; notfound:1
STAT 221.235.53.163:11212:TCP:ascii-100000 avg_latency_us:525.188 pending_reqs:0 inflight_reqs:0 closed:1; found:1 local_error:1
END
I0422 11:45:54.106817 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:45:54.106847 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:45:54.106868 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d8003840, fd=12, state=2
I0422 11:45:54.106887 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d8003840, fd=12, evb=0x29b6d68, state=2, events=0
I0422 11:45:54.106909 22580 AsyncSocket.cpp:245] AsyncSocket::destroy(this=0x7fa2d8003840, evb=0x29b6d68, fd=12, state=2
I0422 11:45:54.106922 22580 AsyncSocket.cpp:784] AsyncSocket::closeNow(): this=0x7fa2d8003840, fd_=12, state=2, shutdownFlags=4
I0422 11:45:54.107010 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:45:54.107043 22580 EventBase.cpp:292] EventBase(): Starting loop.
[root@kjwh163 lixq]# I0422 11:46:03.132277 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:46:03.132315 22580 EventBase.cpp:292] EventBase(): Starting loop.

[root@kjwh163 lixq]#
[root@kjwh163 lixq]#
[root@kjwh163 lixq]#
[root@kjwh163 lixq]# echo "stats suspect_servers" |nc 127.0.0.1 7001
I0422 11:46:27.997233 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:46:27.997285 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:46:27.997320 22580 AsyncSocket.cpp:211] new AsyncSocket(0x7fa2d8003840, evb=0x29b6d68, fd=12)
I0422 11:46:27.997354 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d8003840, fd=12, evb=0x29b6d68, state=2, events=2
I0422 11:46:27.997382 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:46:27.997396 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:46:27.997413 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d8003840, fd=12, state=2
END
I0422 11:46:27.997685 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:46:27.997720 22580 EventBase.cpp:292] EventBase(): Starting loop.
I0422 11:46:27.997742 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d8003840, fd=12, state=2
I0422 11:46:27.997761 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d8003840, fd=12, evb=0x29b6d68, state=2, events=0
I0422 11:46:27.997781 22580 AsyncSocket.cpp:245] AsyncSocket::destroy(this=0x7fa2d8003840, evb=0x29b6d68, fd=12, state=2
I0422 11:46:27.997795 22580 AsyncSocket.cpp:784] AsyncSocket::closeNow(): this=0x7fa2d8003840, fd_=12, state=2, shutdownFlags=4
I0422 11:46:27.997880 22580 EventBase.cpp:421] EventBase(): Done with loop.
I0422 11:46:27.997910 22580 EventBase.cpp:292] EventBase(): Starting loop.

[alikhtarov]

Thank you, I think I know what the issue is.
The problem is that internally, we rely on a metaget command which would tell us what's the current TTL of a value in the warm pool is. The open source memcached does not support this operation, and there's no way to query for the current TTL, so the best you can do is to set the values with some predefined TTL.

This is confusing, so we will change the default so that the open source version doesn't assume this metaget operation exists.

A workaround is to specify a TTL explicitly. For example if you want values to be set with TTL=1000 seconds, in your config you should specify 'exptime' field for the WarmUpRoute:

{
  "pools": {
    "cold": { "servers": [ "xx.xx.xx.xx:11211" ] },
    "warm": { "servers": [ "xx.xx.xx.xx:11212" ] }
  },
  "route": {
    "type": "WarmUpRoute",
    "cold": "PoolRoute|cold",
    "warm": "PoolRoute|warm",
    "exptime": 1000
  }
}

I found it from these lines:

I0422 11:41:05.363620 22580 AsyncSocket.cpp:1226] AsyncSocket::handleRead() this=0x7fa2d800c620, fd=24, state=2
I0422 11:41:05.363653 22580 AsyncSocket.cpp:1694] AsyncSocket::updateEventRegistration(this=0x7fa2d800c620, fd=24, evb=0x29b6d68, state=2, events=0
I0422 11:41:05.363675 22580 AsyncSocket.cpp:729] AsyncSocket::close(): this=0x7fa2d800c620, fd_=24, state=2, shutdownFlags=0

from looking at AsyncSocket.cpp it looks like we tried to read data from the socket, and got EOF (remote end closed). This could happen if memcached got unexpected data over the wire, which is consistent with sending an unknown operation like metaget.

[lixiaoqiang-huoli]

thanks a lot ,it works fine now