Client doesn't sync (failed to start rpc server: 511 Unknown service)

4ley commented 9 years ago

Versions

Client: Seafile 4.0.5 on Windows 8 Pro x64 Server: Seafile 4.0.2 on Debian GNU/Linux 7.7 (wheezy)

Problem

I've a relatively large library (~ 160 GB, ~ 200k files). On one of my PCes some strange errors appear. I've installed Seafile, chose "sync with existing directory" option and selected an empty directory. It was showing me "downloading..." for a while than it started to count percents. The strange thing, it was showing 1%, 2%, 3% and then it went back to 0%, then again 1% to 12% then back to 1%. This was suspicious, so I started to check the logs. Basically I saw two things, which look strange:

[RPC] failed to start rpc server: 511 Unknown service.
...
[Sea RPC] Bad response: 102 processor is dead.

Please see the attached logs for more information.

Client log files

applet.log

...
[01/06/15 12:28:23][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 12:28:23][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 12:28:24][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 12:28:24][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 12:28:24][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 12:42:46]read from connfd error: No error.
[01/06/15 12:42:46][RPC] failed to read response.
[01/06/15 12:42:47][RPC] failed to read response.
[01/06/15 12:42:47][RPC] failed to read response.
[01/06/15 12:42:47][RPC] failed to read response.
[01/06/15 12:42:47][RPC] failed to read response.
...
[01/06/15 12:43:19][RPC] failed to start rpc server: 511 Unknown service.
[01/06/15 14:44:03]read from connfd error: No error.
...
[01/07/15 00:26:55][Sea RPC] Bad response: 515 peer down.
[01/07/15 00:26:55][Sea RPC] Bad response: 102 processor is dead.
[01/07/15 00:26:55][Sea RPC] Bad response: 102 processor is dead.
[01/07/15 00:26:56][Sea RPC] Bad response: 102 processor is dead.
[01/07/15 00:26:56][Sea RPC] Bad response: 102 processor is dead.
...

seafile.log

...
[01/06/15 12:28:24] seaf-daemon.c(490): starting seafile client 4.0.5
[01/06/15 12:28:24] seaf-daemon.c(492): seafile source code version 57f2ba8fc2a4e1ce0f99713cde3670254baf1268
[01/06/15 12:28:24] ../common/mq-mgr.c(60): [mq client] mq cilent is started
[01/06/15 12:28:24] ../common/mq-mgr.c(106): [mq mgr] publish to hearbeat mq: seafile.heartbeat
[01/06/15 12:28:24] clone-mgr.c(245): add relay before clone, cloud.domain.com:10001
[01/06/15 12:28:24] clone-mgr.c(744): Transition clone state for 6356edb3 from [init] to [connect].
[01/06/15 12:28:29] clone-mgr.c(744): Transition clone state for 6356edb3 from [connect] to [connect].
[01/06/15 12:28:29] clone-mgr.c(744): Transition clone state for 6356edb3 from [connect] to [fetch].
[01/06/15 12:28:30] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'init') --> ('normal', 'check')
[01/06/15 12:28:30] processors/check-tx-v3-proc.c(313): repo version is 1, protocol version is 7.
[01/06/15 12:28:30] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'check') --> ('normal', 'commit')
[01/06/15 12:28:30] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'commit') --> ('normal', 'fs')
[01/06/15 12:31:59] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'fs') --> ('normal', 'get-chunk-server')
[01/06/15 12:31:59] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'get-chunk-server') --> ('normal', 'data')
[01/06/15 12:32:29] block-tx-client.c(759): Data connection is closed by the server.
[01/06/15 12:33:14] block-tx-client.c(935): Recv timeout.
[01/06/15 12:33:59] block-tx-client.c(935): Recv timeout.
[01/06/15 12:34:44] block-tx-client.c(935): Recv timeout.
...

ccnet.log

[01/06/15 12:28:22] ccnet-daemon.c(193): starting ccnet client 4.0.5
[01/06/15 12:28:22] ccnet-daemon.c(195): ccnet source code version 6b8e8718825af85f481b7da61e919d848af2d56d
[01/06/15 12:28:22] ../common/session.c(395): Listen on 127.0.0.1 13419
[01/06/15 12:28:22] ../common/session.c(267): Update pubinfo file
[01/06/15 12:28:22] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:23] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:23] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:24] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:24] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:24] ../common/session.c(375): Accepted a local client
[01/06/15 12:28:24] ../common/processors/rcvcmd-proc.c(492): Add server b6e781b1 cloud.domain.com:10001
[01/06/15 12:28:24] ../common/connect-mgr.c(364): [Conn] Start outgoing connect to (null)(b6e781b1e8) 83.125.20.159:10001
[01/06/15 12:28:25] ../common/connect-mgr.c(289): [Conn] Peer (null) (b6e781b1e8) connected
[01/06/15 12:31:59] ../common/peer.c(766): Delayed update from local-4(a4a71e51), id is 1008, 500 Shutdown
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor service-proxy-proc(-1017) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor service-stub-proc(1001) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor rpcserver-proc(-1002) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor mqserver-proc(-1001) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor mqserver-proc(-1002) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(943): Local peer down
[01/06/15 12:42:46] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/06/15 12:42:46] ../common/peer.c(949): [Net Error] Peer Cloud (b6e781b1e8) down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor rpcserver-proc(-1001) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processor.c(218): [Proc] Shutdown processor keepalive2-proc(-1005) for bad update: 515 peer down
[01/06/15 12:42:46] ../common/processors/keepalive2-proc.c(475): [Keepalive] Error from peer 515 peer down
[01/06/15 12:42:53] ../common/connect-mgr.c(289): [Conn] Peer Cloud (b6e781b1e8) connected
...

freeplant commented 9 years ago

Can you try the new v4.0.6?

4ley commented 9 years ago

v4.0.6 seems to work. At least no error messages. I will close the ticket, when sync went through.

4ley commented 9 years ago

The problem seems to persist.

Client log files

applet.log

[01/15/15 20:02:00]starting ccnet:  ("-c", "C:/Users/name/ccnet") 
[01/15/15 20:02:01]trying to connect to ccnet daemon...
[01/15/15 20:02:01]connected to ccnet daemon
[01/15/15 20:02:02]seafile daemon is now running
[01/15/15 20:02:02][Rpc Client] connected to daemon
[01/15/15 20:02:02][MessageListener] connected to daemon
[01/15/15 20:02:02][RPC] failed to start rpc server: 511 Unknown service.
...
[01/15/15 20:02:02][RPC] failed to start rpc server: 511 Unknown service.
[01/15/15 20:02:02]starting seaf-daemon:  ("-c", "C:/Users/name/ccnet", "-d", "D:/Seafile/seafile-data", "-w", "D:/Seafile") 
[01/15/15 20:02:02]request failed for http://seafile.com/api/client-versions/?id=xxx&v=windows-4.0.6: status code 500
[01/15/15 20:08:21][api] network error for https://cloud.domain.com/api2/unseen_messages/: Verbindung beendet
[01/15/15 20:19:07][api] network error for https://cloud.domain.com/api2/unseen_messages/: Verbindung beendet
[01/15/15 20:27:49]unknown sync status: cancel pending
[01/15/15 20:27:50]unknown sync status: cancel pending
[01/15/15 20:27:50]unknown sync status: cancel pending
[01/15/15 20:27:50]unknown sync status: cancel pending
[01/15/15 20:27:51]unknown sync status: cancel pending
[01/15/15 20:27:51]unknown sync status: cancel pending
...
[01/15/15 20:31:10][Daemon Mgr] stopping ccnet/seafile daemon

seafile.log

[01/15/15 20:02:02] seaf-daemon.c(490): starting seafile client 4.0.6
[01/15/15 20:02:02] seaf-daemon.c(492): seafile source code version 4bc0effee428cd23829b35e6798d83cf42713dc9
[01/15/15 20:02:02] ../common/mq-mgr.c(60): [mq client] mq cilent is started
[01/15/15 20:02:02] ../common/mq-mgr.c(106): [mq mgr] publish to hearbeat mq: seafile.heartbeat
[01/15/15 20:02:04] sync-mgr.c(569): Repo 'MyRepo' sync state transition from 'synchronized' to 'uploading'.
[01/15/15 20:02:04] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'init') --> ('normal', 'check')
[01/15/15 20:02:04] processors/check-tx-v3-proc.c(313): repo version is 1, protocol version is 7.
[01/15/15 20:02:04] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'check') --> ('normal', 'commit')
[01/15/15 20:02:04] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'commit') --> ('normal', 'fs')
[01/15/15 20:02:04] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'fs') --> ('normal', 'check-blocks')
[01/15/15 20:02:04] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'check-blocks') --> ('normal', 'get-chunk-server')
[01/15/15 20:02:05] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'get-chunk-server') --> ('normal', 'data')
[01/15/15 20:02:13] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'data') --> ('normal', 'update-branch')
[01/15/15 20:02:13] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'update-branch') --> ('finished', 'finished')
[01/15/15 20:02:13] sync-mgr.c(569): Repo 'MyRepo' sync state transition from 'uploading' to 'initializing'.
[01/15/15 20:02:13] sync-mgr.c(1385): Removing blocks for repo MyRepo(6356edb3).
[01/15/15 20:02:14] sync-mgr.c(569): Repo 'MyRepo' sync state transition from 'synchronized' to 'committing'.
[01/15/15 20:27:49] sync-mgr.c(569): Repo 'MyRepo' sync state transition from 'committing' to 'cancel pending'.

ccnet.log

[01/15/15 20:02:00] ccnet-daemon.c(193): starting ccnet client 4.0.6
[01/15/15 20:02:00] ccnet-daemon.c(195): ccnet source code version 6b8e8718825af85f481b7da61e919d848af2d56d
[01/15/15 20:02:01] ../common/session.c(395): Listen on 127.0.0.1 13419
[01/15/15 20:02:01] ../common/session.c(267): Update pubinfo file
[01/15/15 20:02:01] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/session.c(375): Accepted a local client
[01/15/15 20:02:02] ../common/processors/rcvcmd-proc.c(492): Add server b6e781b1 cloud.domain.com:10001
[01/15/15 20:02:02] ../common/connect-mgr.c(364): [Conn] Start outgoing connect to (null)(b6e781b1e8) 127.42.0.0:10001
[01/15/15 20:02:02] ../common/connect-mgr.c(289): [Conn] Peer (null) (b6e781b1e8) connected
[01/15/15 20:02:05] ../common/peer.c(766): Delayed update from local-4(9e90aec6), id is 1009, 500 Shutdown
[01/15/15 20:31:10] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/15/15 20:31:10] ../common/peer.c(943): Local peer down
[01/15/15 20:31:10] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/15/15 20:31:10] ../common/peer.c(943): Local peer down
[01/15/15 20:31:10] ../common/peer.c(941): libevent got an error! what=33, errno=0 (No error)
[01/15/15 20:31:10] ../common/peer.c(943): Local peer down
[01/15/15 20:31:10] ../common/processor.c(218): [Proc] Shutdown processor mqserver-proc(-1002) for bad update: 515 peer down
[01/15/15 20:31:10] ../common/processor.c(292): [Proc] peer 9e90aec6ff, Shutdown processor service-stub-proc(1001) for bad response: 515 peer down
[01/15/15 20:31:10] ../common/processor.c(292): [Proc] peer 9e90aec6ff, Shutdown processor service-proxy-proc(-1010) for bad response: 515 peer down
[01/15/15 20:31:10] ../common/processor.c(218): [Proc] Shutdown processor rpcserver-proc(-1001) for bad update: 515 peer down

killing commented 9 years ago

Looks like you canceled the syncing when the client is indexing the files. But I don't understand why it takes so long. What operations did you do before this happened?

4ley commented 9 years ago

Nothing particular. I clicked unsync library once it had a green tick the first time. Restructured some files/folders, clicked sync library (selected directory etc.) and then this appeared. At some point the client shows me just an orange exclamation mark.

4ley commented 9 years ago

Here are some more logs

seafile.log

[01/20/15 11:30:42] processors/check-tx-v3-proc.c(313): repo version is 1, protocol version is 7.
[01/20/15 11:30:42] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'check') --> ('normal', 'commit')
[01/20/15 11:30:42] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'commit') --> ('normal', 'fs')
[01/20/15 11:30:43] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'fs') --> ('normal', 'get-chunk-server')
[01/20/15 11:30:43] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'get-chunk-server') --> ('normal', 'data')
[01/20/15 11:30:44] block-tx-client.c(168): connect error: Connection refused [WSAECONNREFUSED ].
[01/20/15 11:30:44] transfer-mgr.c(347): Transfer repo '6356edb3': ('normal', 'data') --> ('error', 'finished'): Failed to download blocks.
[01/20/15 11:30:44] sync-mgr.c(636): Repo 'MyRepo' sync state transition from downloading to 'error': 'Error occured in download.'.
[01/20/15 11:31:12] sync-mgr.c(569): Repo 'MyRepo' sync state transition from 'synchronized' to 'downloading'.
[01/20/15 11:31:12] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'init') --> ('normal', 'check')
[01/20/15 11:31:12] processors/check-tx-v3-proc.c(313): repo version is 1, protocol version is 7.
[01/20/15 11:31:12] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'check') --> ('normal', 'commit')
[01/20/15 11:31:13] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'commit') --> ('normal', 'fs')
[01/20/15 11:31:13] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'fs') --> ('normal', 'get-chunk-server')
[01/20/15 11:31:13] transfer-mgr.c(310): Transfer repo '6356edb3': ('normal', 'get-chunk-server') --> ('normal', 'data')
[01/20/15 11:31:14] block-tx-client.c(168): connect error: Connection refused [WSAECONNREFUSED ].
[01/20/15 11:31:14] transfer-mgr.c(347): Transfer repo '6356edb3': ('normal', 'data') --> ('error', 'finished'): Failed to download blocks.
[01/20/15 11:31:14] sync-mgr.c(636): Repo 'MyRepo' sync state transition from downloading to 'error': 'Error occured in download.'.

chuegel commented 9 years ago

Same issue here toot with 4.0.6

[02/23/15 23:28:15] ../common/connect-mgr.c(289): [Conn] Peer (null) (c87296b84a) connected
[02/23/15 23:48:32] ../common/peer.c(943): Local peer down
[02/23/15 23:48:32] ../common/peer.c(943): Local peer down
[02/23/15 23:48:32] ../common/peer.c(943): Local peer down
[02/23/15 23:48:32] ../common/processor.c(218): [Proc] Shutdown processor mqserver-proc(-1002) for bad update: 515 peer down
[02/23/15 23:48:32] ../common/processor.c(292): [Proc] peer 8d3b817369, Shutdown processor service-stub-proc(1001) for bad response: 515 peer down
[02/23/15 23:48:32] ../common/processor.c(292): [Proc] peer 8d3b817369, Shutdown processor service-proxy-proc(-1010) for bad response: 515 peer down
[02/23/15 23:48:32] ../common/processor.c(218): [Proc] Shutdown processor rpcserver-proc(-1001) for bad update: 515 peer down

a740122 commented 9 years ago

Client: Seafile 4.0.6 on Windows 7 Home x64 Server: Seafile 4.0.6 on Ubuntu 14.10

I have the same status on internet, but local lan is better. I have router and using nat to seafile server on internet. look like PRC server port in using. have any idea?

ccnet.log [02/27/15 22:25:31] ccnet-daemon.c(193): starting ccnet client 4.0.6 [02/27/15 22:25:31] ccnet-daemon.c(195): ccnet source code version 6b8e8718825af85f481b7da61e919d848af2d56d [02/27/15 22:25:31] ../common/session.c(395): Listen on 127.0.0.1 13419 [02/27/15 22:25:31] ../common/session.c(267): Update pubinfo file [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client [02/27/15 22:25:32] ../common/session.c(375): Accepted a local client

applet.log [02/27/15 22:25:31]starting ccnet: ("-c", "C:/Users/ASUS/ccnet") [02/27/15 22:25:32]trying to connect to ccnet daemon... [02/27/15 22:25:32]connected to ccnet daemon [02/27/15 22:25:32]seafile daemon is now running [02/27/15 22:25:32][Rpc Client] connected to daemon [02/27/15 22:25:32][MessageListener] connected to daemon [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32]starting seaf-daemon: ("-c", "C:/Users/ASUS/ccnet", "-d", "D:/seafile/Seafile/seafile-data", "-w", "D:/seafile/Seafile") [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:32][RPC] failed to start rpc server: 511 Unknown service. [02/27/15 22:25:33]request failed for http://seafile.com/api/client-versions/?id=4d7234bc&v=windows-4.0.6: status code 500

seafile.log [02/27/15 22:25:32] seaf-daemon.c(490): starting seafile client 4.0.6 [02/27/15 22:25:32] seaf-daemon.c(492): seafile source code version 4bc0effee428cd23829b35e6798d83cf42713dc9 [02/27/15 22:25:32] ../common/mq-mgr.c(60): [mq client] mq cilent is started [02/27/15 22:25:32] ../common/mq-mgr.c(106): [mq mgr] publish to hearbeat mq: seafile.heartbeat [02/27/15 22:25:32] clone-mgr.c(245): add relay before clone, www.xxxx.tw:10001 [02/27/15 22:25:32] clone-mgr.c(744): Transition clone state for 0efb76fa from [init] to [connect]. [02/27/15 22:25:54] clone-mgr.c(245): add relay before clone, www.xxxx.tw:20001 [02/27/15 22:25:54] clone-mgr.c(744): Transition clone state for 6cd179c1 from [init] to [connect].

galvanopus commented 8 years ago

Were you able to solve your issue? I suggest it is the same as mine: #1425.

haiwen / seafile