[EDIT] it’s not the pydio.rest.jobs
service twice in cells ps
as I wrote below, one is pydio.grpc.jobs
which is not running, one is pydio.rest.jobs
which is running, I misread
Hey,
thanks for the quick response!
I did nc -lp port_number > /dev/null
and then in a separate window lsof -i :port_number
for all the port numbers that appear in the starting log, they all bind to nc as I would expect. My Firewall is ufw, even if I turn it off it doesn’t work so I doubt that’s the problem.
I’m not running SELinux but AppArmor is built into the Kernel. I’ve tried to disable the service as described here (I didn’t disable it in the kernel, only disabled the systemd service) and it didn’t make a difference.
I did notice something odd though, when I run cells ps
I see pydio.rest.jobs
twice, once it’s enabled and once disabled. Could it be clashing with itself?
I wrote Strato an Email asking whether they have some firewall or are blocking any ports even though I doubt it because a dig into the security section of their website didn’t reveal anything.
Here are the parts that seemed error-relevant to me of the starting log of cells:
09:57:34 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:34+02:00","msg":"[pydio.grpc.log] Cannot open bleve index /var/cells/services/pydio.grpc.jobs/tasklogs.bleve cannot create new index, path already exists"}
09:57:34 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:34+02:00","logger":"pydio.grpc.jobs","msg":"started"}
09:57:37 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:37+02:00","logger":"pydio.grpc.tasks","msg":"Run Job resync-ds-cellsdata on demand","SpanUuid":"140626b6-9cf7-11eb-b6bd-0242947f3aaf"}
09:57:37 <Hostname>: panic: runtime error: index out of range [-1]
09:57:37 <Hostname>: goroutine 740 [running]:
09:57:37 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).getWriteIndex(...)
09:57:37 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:119
09:57:37 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).watchInserts(0xc0004add80)
09:57:37 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:199 +0x590
09:57:37 <Hostname>: created by github.com/pydio/cells/broker/log.(*SyslogServer).Open
09:57:37 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:114 +0x3eb
09:57:37 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:37+02:00","logger":"pydio.gateway.proxy","msg":"Restarting proxy","caddyfile":"\n\n\n\n\n\n\n10.0.0.1:8085 {\n\t\n\n\t\n\n\tproxy /a 10.0.0.1:35361 {\n\t\twithout /a\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\tproxy /oidc 10.0.0.1:34661 {\n\t\tinsecure_skip_verify\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\tproxy /io 10.0.0.1:40359 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t\theader_downstream Content-Security-Policy \"script-src 'none'\"\n\t\theader_downstream X-Content-Security-Policy \"sandbox\"\n\t}\n\tproxy /data 10.0.0.1:40359 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t\theader_downstream Content-Security-Policy \"script-src 'none'\"\n\t\theader_downstream X-Content-Security-Policy \"sandbox\"\n\t}\n\tproxy /ws 10.0.0.1:35121 {\n\t\twebsocket\n\t\twithout /ws\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\tproxy /dav 10.0.0.1:34189 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t\theader_downstream Content-Security-Policy \"script-src 'none'\"\n\t\theader_downstream X-Content-Security-Policy \"sandbox\"\n\t}\n\t\n\n\tproxy /plug/ 10.0.0.1:35449 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t\theader_downstream Cache-Control \"public, max-age=31536000\"\n\t}\n\tproxy /public/ 10.0.0.1:35449 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\tproxy /public/plug/ 10.0.0.1:35449 {\n\t\twithout /public\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t\theader_downstream Cache-Control \"public, max-age=31536000\"\n\t}\n\tproxy /user/reset-password/ 10.0.0.1:35449 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\t\n\tproxy /robots.txt 10.0.0.1:35449 {\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\t\n\tproxy /login 10.0.0.1:35449/gui {\n\t\twithout /login\n\t\theader_upstream Host <External address>\n\t\theader_upstream X-Real-IP {remote}\n\t\theader_upstream X-Forwarded-Proto {scheme}\n\t}\n\n\n\tproxy /grpc https://10.0.0.1:33767 {\n\t\twithout /grpc\n\t\tinsecure_skip_verify\n\t}\n\t\n\trewrite {\n\t\tif {>Content-type} has \"application/grpc\"\n\t\tto /grpc/{path}\n\t}\n\n\n\tredir 302 {\n\t\tif {>Content-type} not_has \"application/grpc\"\n\t\tif {path} is /\n\t\t/ /login\n\t}\n\t\n\t\n\t\n proxy /wopi/ 10.0.0.1:45610 {\n transparent\n\t\t\theader_upstream Host <External address>\n\t\t\theader_upstream X-Real-IP {remote}\n\t\t\theader_upstream X-Forwarded-Proto {scheme}\n }\n\n proxy /loleaflet/ http://<External address of collabora>:9980/loleaflet {\n transparent\n insecure_skip_verify\n without /loleaflet/\n }\n\n proxy /hosting/discovery http://<External address of collabora>:9980/hosting/discovery {\n transparent\n insecure_skip_verify\n without /hosting/discovery\n }\n\n proxy /lool/ http://<External address of collabora>:9980/lool/ {\n transparent\n insecure_skip_verify\n websocket\n without /lool/\n }\n \n\t\n\t\n\trewrite {\n\t\tif {path} not_starts_with \"/a/\"\n\t\tif {path} not_starts_with \"/oidc/\"\n\t\tif {path} not_starts_with \"/io\"\n\t\tif {path} not_starts_with \"/data\"\n\t\tif {path} not_starts_with \"/ws/\"\n\t\tif {path} not_starts_with \"/plug/\"\n\t\tif {path} not_starts_with \"/dav\"\n\t\t\n\t\tif {path} not_starts_with \"/wopi/\"\n\t\t\n\t\tif {path} not_starts_with \"/loleaflet/\"\n\t\t\n\t\tif {path} not_starts_with \"/hosting/discovery\"\n\t\t\n\t\tif {path} not_starts_with \"/lool/\"\n\t\t\n\t\tif {path} not_starts_with \"/public/\"\n\t\tif {path} not_starts_with \"/user/reset-password\"\n\t\tif {path} not_starts_with \"/robots.txt\"\n\t\tto {path} {path}/ /login\n\t}\n\n\troot \"/76126d21-b5d9-434a-b3f7-9f968b18f718\"\n\n\t\n\ttls \"/var/cells/certs/190dafab69706a67221c1226360de7dc.pem\" \"/var/cells/certs/190dafab69706a67221c1226360de7dc-key.pem\"\n\terrors \"/var/cells/logs/caddy_errors.log\"\n}\n\n\n\n\n\t"}
09:57:38 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:38+02:00","logger":"pydio.gateway.proxy","msg":"Restart done"}
09:57:39 <Hostname>: {"level":"error","ts":"2021-04-14T09:57:39+02:00","msg":"SubProcess finished with error: trying to restart now"}
09:57:39 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:39+02:00","msg":"[pydio.grpc.log] Cannot open bleve index /var/cells/services/pydio.grpc.jobs/tasklogs.bleve cannot create new index, path already exists"}
09:57:39 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:39+02:00","logger":"pydio.grpc.jobs","msg":"started"}
09:57:42 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:42+02:00","logger":"pydio.grpc.tasks","msg":"Run Job resync-ds-pydiods1 on demand","SpanUuid":"16f9b78e-9cf7-11eb-b6bd-0242947f3aaf"}
09:57:42 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:42+02:00","logger":"pydio.grpc.tasks","msg":"Run Job resync-ds-buvo on demand","SpanUuid":"17081283-9cf7-11eb-b6bd-0242947f3aaf"}
09:57:42 <Hostname>: panic: runtime error: index out of range [-1]
09:57:42 <Hostname>: goroutine 750 [running]:
09:57:42 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).getWriteIndex(...)
09:57:42 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:119
09:57:42 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).watchInserts(0xc000772c00)
09:57:42 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:199 +0x590
09:57:42 <Hostname>: created by github.com/pydio/cells/broker/log.(*SyslogServer).Open
09:57:42 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:114 +0x3eb
09:57:43 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:43+02:00","logger":"pydio.grpc.data.sync.personal","msg":"{\"level\":\"error\",\"ts\":\"2021-04-14T09:57:43+02:00\",\"msg\":\"Streamer PutTaskStream\",\"error\":\"{\\\"id\\\":\\\"go.micro.client\\\",\\\"code\\\":500,\\\"detail\\\":\\\"Error creating stream: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \\\\\\\"trans\\port: Error while dialing dial tcp 10.0.0.1:46218: connect: connection refused\\\\\\\"\\\",\\\"status\\\":\\\"Internal Server Error\\\"}\"}"}
09:57:44 <Hostname>: {"level":"error","ts":"2021-04-14T09:57:44+02:00","msg":"SubProcess finished with error: trying to restart now"}
09:57:44 <Hostname>: {"level":"error","ts":"2021-04-14T09:57:44+02:00","logger":"pydio.grpc.tasks","msg":"Streamer PutTaskStream","error":"{\"id\":\"go.micro.client\",\"code\":500,\"detail\":\"Error creating stream: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \\\"transport: Error while dialing dial tcp 10.0.0.1:46218: connect: connection refused\\\"\",\"status\":\"Internal Server Error\"}"}
09:57:44 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:44+02:00","msg":"[pydio.grpc.log] Cannot open bleve index /var/cells/services/pydio.grpc.jobs/tasklogs.bleve cannot create new index, path already exists"}
09:57:44 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:44+02:00","logger":"pydio.grpc.jobs","msg":"started"}
09:57:56 <Hostname>: panic: runtime error: index out of range [-1]
09:57:56 <Hostname>: goroutine 730 [running]:
09:57:56 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).getWriteIndex(...)
09:57:56 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:119
09:57:56 <Hostname>: github.com/pydio/cells/broker/log.(*SyslogServer).watchInserts(0xc00012d580)
09:57:56 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:199 +0x590
09:57:56 <Hostname>: created by github.com/pydio/cells/broker/log.(*SyslogServer).Open
09:57:56 <Hostname>: github.com/pydio/cells/broker/log/syslog.go:114 +0x3eb
09:57:58 <Hostname>: {"level":"error","ts":"2021-04-14T09:57:58+02:00","msg":"SubProcess finished with error: trying to restart now"}
09:57:58 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:58+02:00","logger":"pydio.grpc.jobs","msg":"started"}
09:57:58 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:58+02:00","msg":"[pydio.grpc.log] Cannot open bleve index /var/cells/services/pydio.grpc.jobs/tasklogs.bleve cannot create new index, path already exists"}
09:57:58 <Hostname>: {"level":"info","ts":"2021-04-14T09:57:58+02:00","logger":"pydio.grpc.jobs","msg":"Setting task 01403925-5626-49e4-84e2-3b2f5fac6614 in error status as it was saved as running"}
09:58:05 <Hostname>: {"level":"error","ts":"2021-04-14T09:58:05+02:00","logger":"pydio.grpc.tasks","msg":"Streamer PutTaskStream","error":"{\"id\":\"go.micro.client\",\"code\":500,\"detail\":\"Error creating stream: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \\\"transport: Error while dialing dial tcp 10.0.0.1:35593: connect: connection refused\\\"\",\"status\":\"Internal Server Error\"}"}
09:58:16 <Hostname>: {"level":"info","ts":"2021-04-14T09:58:16+02:00","logger":"pydio.grpc.tasks","msg":"Run Job internal-prune-jobs on timer event Iso8601Schedule:\"R/2012-06-04T19:25:16.828696-07:03/PT10M\" ","SpanUuid":"2ba9306f-9cf7-11eb-b6bd-0242947f3aaf"}
09:58:26 <Hostname>: {"level":"error","ts":"2021-04-14T09:58:26+02:00","logger":"pydio.grpc.tasks","msg":"Streamer PutTaskStream","error":"{\"id\":\"go.micro.client\",\"code\":500,\"detail\":\"Error creating stream: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \\\"transport: Error while dialing dial tcp 10.0.0.1:35593: connect: connection refused\\\"\",\"status\":\"Internal Server Error\"}"}
09:58:37 <Hostname>: {"level":"info","ts":"2021-04-14T09:58:37+02:00","logger":"pydio.grpc.data.sync.cellsdata","msg":"Got Stats for index://cellsdata","SpanRootUuid":"140626b6-9cf7-11eb-b6bd-0242947f3aaf","SpanParentUuid":"140626b6-9cf7-11eb-b6bd-0242947f3aaf","SpanUuid":"382115db-9cf7-11eb-bfee-0242947f3aaf","stats":{"HasChildrenInfo":false,"HasSizeInfo":false,"Size":0,"Folders":0,"Files":0}}
09:58:37 <Hostname>: {"level":"info","ts":"2021-04-14T09:58:37+02:00","logger":"pydio.grpc.data.sync.cellsdata","msg":"Got Stats for s3://<IP Address>:33099/cellsdata","SpanRootUuid":"140626b6-9cf7-11eb-b6bd-0242947f3aaf","SpanParentUuid":"140626b6-9cf7-11eb-b6bd-0242947f3aaf","SpanUuid":"382115db-9cf7-11eb-bfee-0242947f3aaf","stats":{"HasChildrenInfo":false,"HasSizeInfo":false,"Size":0,"Folders":0,"Files":0}}
09:58:37 <Hostname>: {"level":"error","ts":"2021-04-14T09:58:37+02:00","logger":"pydio.grpc.tasks","msg":"cannot run action actions.internal.prune-jobs: {\"id\":\"\",\"code\":0,\"detail\":\"all SubConns are in TransientFailure, latest connection error: connection error: desc = \\\"transport: Error while dialing dial tcp 10.0.0.1:46218: connect: connection refused\\\" - Request was JobService.DetectStuckTasks on pydio.grpc.jobs - Micro-registry had node(s) : [10.0.0.1:43629]\",\"status\":\"\"}","OperationUuid":"internal-prune-jobs-0192e240","SpanUuid":"2ba9306f-9cf7-11eb-b6bd-0242947f3aaf","OperationUuid":"internal-prune-jobs-0192e240","SchedulerJobUuid":"internal-prune-jobs","SchedulerTaskUuid":"0192e240-c4b6-4ae6-8524-9cffef7e097a","SchedulerTaskActionPath":"ROOT/actions.internal.prune-jobs$0"}
Thanks a lot,
Ben