Cells Sync causes Cells to crash after timeout

Hi all,

For a while now I’m trying to make Cells Sync to work with Pydio Cells but even with all newest versions I can’t get it working…

This is my current environment;

OS: CentOS 7.9.2009
Cells Server version: Pydio Cells Home Edition 3.0.3
Cells Sync version: CellsSync - 0.9.3-dev.202110141545 (I also tried the current stable version)
Apache version: 2.4.52
Database version: MariaDB 10.5.13

Unix Cells-Service Config: vi /etc/systemd/system/cells.service
[Unit]
Description=Pydio Cells
Documentation=https://pydio.com
Wants=network-online.target
After=network-online.target
AssertFileIsExecutable=/opt/pydio/bin/cells

[Service]
User=pydio
Group=pydio
PermissionsStartOnly=true
AmbientCapabilities=CAP_NET_BIND_SERVICE
ExecStart=/opt/pydio/bin/cells start
Restart=on-failure
StandardOutput=journal
StandardError=inherit
LimitNOFILE=65536
TimeoutStopSec=5
KillSignal=INT
SendSIGKILL=yes
SuccessExitStatus=0
WorkingDirectory=/home/pydio

# Add environment variables
Environment=CELLS_LOGS_LEVEL=Production
Environment=CELLS_WORKING_DIR=/var/cells
Environment=CELLS_GRPC_EXTERNAL=33060

[Install]
WantedBy=multi-user.target

Apache Virtual Host config;

<VirtualHost *:80>
    ServerName pydio.mysite.nl

    <IfModule mod_rewrite.c>
       RewriteEngine On
       RewriteCond %{HTTPS} off
       RewriteRule (.*) https://%{HTTP_HOST}%{REQUEST_URI}
    </IfModule>

ErrorLog "/var/log/httpd/sites-cells-error.log"
CustomLog "/var/log/httpd/sites-cells-access.log" common
RewriteCond %{SERVER_NAME} =pydio.mysite.nl
RewriteRule ^ https://%{SERVER_NAME}%{REQUEST_URI} [END,NE,R=permanent]
</VirtualHost>

<IfModule mod_ssl.c>
<VirtualHost *:443>
    ServerName pydio.mysite.nl
	
Protocols h2 h2c http/1.1
  H2Direct on
  AllowEncodedSlashes On
  RewriteEngine On
  SSLEngine On
  SSLProxyEngine On

    # The order of the directives matters.
    # If Cells is not running with https, consider using ws instead of wss
    ProxyPassMatch "/ws/(.*)" ws://10.10.10.1:8080/ws/$1 nocanon

    # This rewrite condition is required if using Cells-Sync, 
	# Using h2c because cells is not running with https
     RewriteCond %{HTTP:Content-Type} =application/grpc [NC]
     RewriteRule /(.*) h2c://10.10.10.1:8080/$1 [P,L]

    ProxyPass "/" "http://10.10.10.1:8080/" retry=1 acquire=3000 timeout=600 Keepalive=On
    ProxyPassReverse "/" "http://10.10.10.1:8080/"

ErrorLog "/var/log/httpd/sites-cells-error.log"
CustomLog "/var/log/httpd/sites-cells-access.log" common

SSLCertificateFile /etc/letsencrypt/live/pydio.mysite.nl/cert.pem
SSLCertificateKeyFile /etc/letsencrypt/live/pydio.mysite.nl/privkey.pem
SSLCertificateChainFile /etc/letsencrypt/live/pydio.mysite.nl/chain.pem
Include /etc/letsencrypt/options-ssl-apache.conf

</VirtualHost>
</IfModule>
Sites Configuration:
[root@server1b vhosts]# cells configure sites
The following sites are currently defined:
+---+------------------------+--------+------------------------------------+
| # |        BIND(S)         |  TLS   |            EXTERNAL URL            |
+---+------------------------+--------+------------------------------------+
| 0 | http://10.10.10.1:8080 | No Tls | https://pydio.mysite.nl |
+---+------------------------+--------+------------------------------------+
Check if port is listening:
[root@server1b ~]# netstat -tunlp | grep 8080
tcp6       0      0 :::8080                 :::*                    LISTEN      2539/cells
[root@server1b ~]# telnet 10.10.10.1 8080
Trying 10.10.10.1...
Connected to 10.10.10.1.
Escape character is '^]'.
Cells services status:
[root@server1b ~]# cells ps
 GENERIC SERVICES
 # data
 pydio.test.objects                      [X]
 # gateway
 pydio.gateway.data                      [X]
 pydio.gateway.dav                       [X]
 pydio.gateway.grpc                      [ ]
 pydio.gateway.grpc.clear                [X]
 pydio.gateway.proxy                     [X]
 pydio.gateway.rest                      [X]
 pydio.gateway.websocket                 [X]
 pydio.gateway.wopi                      [X]

 GRPC SERVICES
 # broker
 pydio.grpc.activity                     [X]
 pydio.grpc.chat                         [X]
 pydio.grpc.log                          [X]
 pydio.grpc.mailer                       [X]
 # data
 pydio.grpc.data-key                     [X]
 pydio.grpc.docstore                     [X]
 pydio.grpc.meta                         [X]
 pydio.grpc.search                       [X]
 pydio.grpc.tree                         [X]
 pydio.grpc.versions                     [X]
 # datasource
 pydio.grpc.data.index                   [X]
 pydio.grpc.data.index.cellsdata         [X]
 pydio.grpc.data.index.personal          [X]
 pydio.grpc.data.index.pydio8            [X]
 pydio.grpc.data.index.pydiods1          [X]
 pydio.grpc.data.index.thumbnails        [X]
 pydio.grpc.data.index.versions          [X]
 pydio.grpc.data.objects                 [X]
 pydio.grpc.data.objects.local1          [X]
 pydio.grpc.data.sync                    [X]
 pydio.grpc.data.sync.cellsdata          [X]
 pydio.grpc.data.sync.personal           [X]
 pydio.grpc.data.sync.pydio8             [X]
 pydio.grpc.data.sync.pydiods1           [X]
 pydio.grpc.data.sync.thumbnails         [X]
 pydio.grpc.data.sync.versions           [X]
 # discovery
 pydio.grpc.broker                       [X]
 pydio.grpc.config                       [X]
 pydio.grpc.registry                     [X]
 pydio.grpc.update                       [X]
 # frontend
 pydio.grpc.statics                      [X]
 # idm
 pydio.grpc.acl                          [X]
 pydio.grpc.oauth                        [X]
 pydio.grpc.policy                       [X]
 pydio.grpc.role                         [X]
 pydio.grpc.token                        [X]
 pydio.grpc.user                         [X]
 pydio.grpc.user-key                     [X]
 pydio.grpc.user-meta                    [X]
 pydio.grpc.workspace                    [X]
 # scheduler
 pydio.grpc.jobs                         [X]
 pydio.grpc.tasks                        [X]
 pydio.grpc.timer                        [X]

 REST SERVICES
 # broker
 pydio.rest.activity                     [X]
 pydio.rest.log                          [X]
 pydio.rest.mailer                       [X]
 # data
 pydio.rest.meta                         [X]
 pydio.rest.search                       [X]
 pydio.rest.templates                    [X]
 pydio.rest.tree                         [X]
 # discovery
 pydio.rest.config                       [X]
 pydio.rest.update                       [X]
 # frontend
 pydio.rest.frontend                     [X]
 pydio.web.statics                       [X]
 # idm
 pydio.rest.acl                          [X]
 pydio.rest.auth                         [X]
 pydio.rest.graph                        [X]
 pydio.rest.policy                       [X]
 pydio.rest.role                         [X]
 pydio.rest.share                        [X]
 pydio.rest.user                         [X]
 pydio.rest.user-meta                    [X]
 pydio.rest.workspace                    [X]
 pydio.web.oauth                         [X]
 # scheduler
 pydio.rest.jobs                         [X]
Browser error:

503 error:
Service Unavailable
The server is temporarily unable to service your request due to maintenance downtime or capacity problems. Please try again later.

Access Log: tail -f /var/log/httpd/sites-cells-access.log
x.x.x.x - - [12/Jan/2022:09:48:09 +0100] "GET /oidc/.well-known/openid-configuration HTTP/2.0" 200 1407
x.x.x.x - - [12/Jan/2022:09:48:09 +0100] "GET /oidc/oauth2/auth?client_id=cells-sync&redirect_uri=http%3A%2F%2Flocalhost%3A3636%2Fservers%2Fcallback&response_type=code&scope=openid%20email%20profile%20pydio%20offline&state=7adf191d6e2b4648a17fab44c1665bc2&code_challenge=9fNih35KzENJJTMNc0qWzrt6_NXEjoQ_MYNXAfBUr5Y&code_challenge_method=S256&response_mode=query HTTP/2.0" 200 -
x.x.x.x - - [12/Jan/2022:09:48:09 +0100] "GET /oidc/oauth2/auth?client_id=cells-sync&redirect_uri=http%3A%2F%2Flocalhost%3A3636%2Fservers%2Fcallback&response_type=code&scope=openid%20email%20profile%20pydio%20offline&state=7adf191d6e2b4648a17fab44c1665bc2&code_challenge=9fNih35KzENJJTMNc0qWzrt6_NXEjoQ_MYNXAfBUr5Y&code_challenge_method=S256&response_mode=query HTTP/2.0" 500 -
x.x.x.x - - [12/Jan/2022:09:53:12 +0100] "GET /oidc/oauth2/auth?client_id=cells-sync&redirect_uri=http%3A%2F%2Flocalhost%3A3636%2Fservers%2Fcallback&response_type=code&scope=openid%20email%20profile%20pydio%20offline&state=7adf191d6e2b4648a17fab44c1665bc2&code_challenge=9fNih35KzENJJTMNc0qWzrt6_NXEjoQ_MYNXAfBUr5Y&code_challenge_method=S256&response_mode=query HTTP/2.0" 503 299
x.x.x.x - - [12/Jan/2022:09:53:12 +0100] "GET /favicon.ico HTTP/2.0" 503 299
x.x.x.x - - [12/Jan/2022:09:53:15 +0100] "GET /ws/event HTTP/1.1" 303 41
Error Log: tail -f /var/log/httpd/sites-cells-error.log
[Wed Jan 12 09:53:11.200439 2022] [proxy_http:error] [pid 16390:tid 140625869231872] (20014)Internal error (specific information not available): [remote x.x.x.x:36507] AH01102: error reading status line from remote server 10.10.10.1:8080, referer: http://localhost:3636/
[Wed Jan 12 09:53:12.389843 2022] [proxy:error] [pid 16390:tid 140625869231872] (111)Connection refused: AH00957: http: attempt to connect to 10.10.10.1:8080 (10.10.10.1) failed
[Wed Jan 12 09:53:12.389929 2022] [proxy_http:error] [pid 16390:tid 140625869231872] [remote x.x.x.x:36352] AH01114: HTTP: failed to make connection to backend: 10.10.10.1, referer: http://localhost:3636/
[Wed Jan 12 09:53:12.444683 2022] [proxy:error] [pid 16390:tid 140625869231872] (111)Connection refused: AH00957: http: attempt to connect to 10.10.10.1:8080 (10.10.10.1) failed
[Wed Jan 12 09:53:12.444725 2022] [proxy_http:error] [pid 16390:tid 140625869231872] [remote x.x.x.x:36352] AH01114: HTTP: failed to make connection to backend: 10.10.10.1, referer: https://pydio.mysite.nl/oidc/oauth2/auth?client_id=cells-sync&redirect_uri=http%3A%2F%2Flocalhost%3A3636%2Fservers%2Fcallback&response_type=code&scope=openid%20email%20profile%20pydio%20offline&state=7adf191d6e2b4648a17fab44c1665bc2&code_challenge=9fNih35KzENJJTMNc0qWzrt6_NXEjoQ_MYNXAfBUr5Y&code_challenge_method=S256&response_mode=query

pydio log: tail -f /var/cells/logs/pydio.log

A lot of these errors (also when not trying to connect with CellsSync):

2022-01-12T13:32:28.803+0100 ERROR pydio.grpc.tasks 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.10.10.1:46380: connect: connection refused\\\"\",\"status\":\"Internal Server Error\"}"}

When the error page in the browser occurs this shows in this logging:

2022-01-12T13:39:50.886+0100    INFO            Cancelling main context
2022-01-12T13:39:50.886+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.886+0100    ERROR   pydio.grpc.tasks        Streamer PutTaskStream  {"error": "{\"id\":\"go.micro.client\",\"code\":408,\"detail\":\"context canceled\",\"status\":\"Request Timeout\"}"}
2022-01-12T13:39:50.887+0100    INFO    pydio.grpc.tasks        Stopping
2022-01-12T13:39:50.887+0100    INFO    pydio.grpc.data.sync.personal   Stopping
2022-01-12T13:39:50.887+0100    INFO    pydio.grpc.data.sync.personal   Stopping configs watch
2022-01-12T13:39:50.888+0100    INFO            Cancelling main context
2022-01-12T13:39:50.888+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.888+0100    INFO            Cancelling main context
2022-01-12T13:39:50.888+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.888+0100    INFO    pydio.grpc.data.index.pydio8    Stopping
2022-01-12T13:39:50.889+0100    INFO    pydio.grpc.data.sync.pydiods1   Stopping
2022-01-12T13:39:50.889+0100    INFO    pydio.grpc.data.sync.pydiods1   Stopping configs watch
2022-01-12T13:39:50.890+0100    INFO            Cancelling main context
2022-01-12T13:39:50.890+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.890+0100    INFO    pydio.grpc.search       Stopping
2022-01-12T13:39:50.890+0100    INFO            Cancelling main context
2022-01-12T13:39:50.890+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.891+0100    INFO    pydio.grpc.data.index.thumbnails        Stopping
2022-01-12T13:39:50.891+0100    INFO            Cancelling main context
2022-01-12T13:39:50.891+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.892+0100    INFO    pydio.grpc.data.sync.versions   Stopping
2022-01-12T13:39:50.892+0100    INFO    pydio.grpc.data.sync.versions   Stopping configs watch
2022-01-12T13:39:50.892+0100    INFO            Cancelling main context
2022-01-12T13:39:50.892+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.892+0100    INFO            Cancelling main context
2022-01-12T13:39:50.892+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.892+0100    INFO    pydio.grpc.data.index.versions  Stopping
2022-01-12T13:39:50.892+0100    INFO            Cancelling main context
2022-01-12T13:39:50.893+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.893+0100    INFO    pydio.grpc.data.index.pydiods1  Stopping
2022-01-12T13:39:50.893+0100    INFO    pydio.grpc.data.index.personal  Stopping
2022-01-12T13:39:50.893+0100    INFO            Cancelling main context
2022-01-12T13:39:50.894+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.894+0100    INFO            Cancelling main context
2022-01-12T13:39:50.894+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.894+0100    INFO    pydio.grpc.data.sync.cellsdata  Stopping
2022-01-12T13:39:50.894+0100    INFO    pydio.grpc.data.sync.cellsdata  Stopping configs watch
2022-01-12T13:39:50.894+0100    INFO            Cancelling main context
2022-01-12T13:39:50.894+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.895+0100    INFO    pydio.grpc.data.index.cellsdata Stopping
2022-01-12T13:39:50.895+0100    INFO    pydio.grpc.data.objects.local1  Stopping
2022-01-12T13:39:50.896+0100    INFO            Cancelling main context
2022-01-12T13:39:50.896+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.896+0100    INFO    pydio.grpc.data.sync.thumbnails Stopping
2022-01-12T13:39:50.896+0100    INFO    pydio.grpc.data.sync.thumbnails Stopping configs watch
2022-01-12T13:39:50.897+0100    INFO            Cancelling main context
2022-01-12T13:39:50.897+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.909+0100    INFO    pydio.grpc.data.sync.pydio8     Stopping
2022-01-12T13:39:50.909+0100    INFO    pydio.grpc.data.sync.pydio8     Stopping sync task and registry watch
2022-01-12T13:39:50.909+0100    INFO            Cancelling main context
2022-01-12T13:39:50.909+0100    INFO            Disconnecting broker
2022-01-12T13:39:50.921+0100    INFO    pydio.gateway.websocket Stopping
2022-01-12T13:39:50.922+0100    INFO            Cancelling main context
2022-01-12T13:39:50.922+0100    INFO            Disconnecting broker

And this in the /var/cells/logs/caddy_errors.log:

12/Jan/2022:10:55:31 +0100 [ERROR 502 /oidc/oauth2/auth] context canceled

So…
Cells is working just fine with the web interface but when I try to connect with CellsSync it goes bad.
The client is able to GET “/oidc/.well-known/openid-configuration” according to the access-log above, but seem to time out on some OIDC thingie and ends up crashing Cells completely.

Can anybody help me figuring out what’s going wrong and why?
I’m open for any suggestion and am able to change and tweak whatever is necessary!

Thanx a lot in advance!

Hi @Thijs_van_Ree
It’s not clear what is causing the server to completely stop.
Could you try to run it manually (instead of via systemctl) from the command line (as pydio user, and with ulimit properly set in this terminal), until it stops? Maybe we’ll see a crash dump in the command line.