Sauvegarde des photos depuis Cozy Drive ne fonctionne plus


#41

Bonjour,

J’ai lancé avec android studio et un emulateur android qui a le même comportement que mon téléphone, et j’ai réussi à extraire des logs intéressantes. L’application fonctionne excepté la synchronisation.

Voici le passage intéressant intéressant :

indent preformatted text by 4 spaces
02-10 08:23:29.746 12206-12206/io.cozy.drive.mobile W/zygote: Attempt to remove non-JNI local reference, dumping thread
02-10 08:23:35.705 12206-12206/io.cozy.drive.mobile I/chatty: uid=10080(io.cozy.drive.mobile) identical 324 lines
02-10 08:23:35.724 12206-12206/io.cozy.drive.mobile W/zygote: Attempt to remove non-JNI local reference, dumping thread
02-10 08:23:35.735 2320-12300/com.google.android.gms.persistent W/ctxmgr: [AclManager]No 2 for (accnt=account#-517948760#, com.google.android.gms(10013):IndoorOutdoorProducer, vrsn=13280000, 0, 3pPkg = null ,  3pMdlId = null ,  pid = 2320). Was: 3 for 57, account#-517948760#
02-10 08:23:35.740 12206-12206/io.cozy.drive.mobile W/zygote: Attempt to remove non-JNI local reference, dumping thread
02-10 08:23:35.981 12206-12206/io.cozy.drive.mobile I/chatty: uid=10080(io.cozy.drive.mobile) identical 14 lines
02-10 08:23:36.000 12206-12206/io.cozy.drive.mobile W/zygote: Attempt to remove non-JNI local reference, dumping thread
02-10 08:23:36.006 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 8 : %c action %cMEDIA_UPLOAD_ABORT %c@ 08:23:35.981
02-10 08:23:36.006 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(8)] "%c action %cMEDIA_UPLOAD_ABORT %c@ 08:23:35.981", source: file:///android_asset/www/vendors.js (8)
02-10 08:23:36.006 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 8 : console.groupEnd
02-10 08:23:36.006 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(8)] "console.groupEnd", source: file:///android_asset/www/vendors.js (8)
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 33 : Raven is recording exception
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(33)] "Raven is recording exception", source: file:///android_asset/www/vendors.js (33)
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 33 : Unexpected error during the files backup (<html>
    <head><title>504 Gateway Time-out</title></head>
    <body>
    <center><h1>504 Gateway Time-out</h1></center>
    <hr><center>nginx/1.15.5 (Ubuntu)</center>
    </body>
    </html>
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    )
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(33)] "Unexpected error during the files backup (<html>
    <head><title>504 Gateway Time-out</title></head>
    <body>
    <center><h1>504 Gateway Time-out</h1></center>
    <hr><center>nginx/1.15.5 (Ubuntu)</center>
    </body>
    </html>
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    <!-- a padding to disable MSIE and Chrome friendly error page -->
    )", source: file:///android_asset/www/vendors.js (33)
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 8 : %c action %cMEDIA_UPLOAD_END %c@ 08:23:36.004
02-10 08:23:36.009 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(8)] "%c action %cMEDIA_UPLOAD_END %c@ 08:23:36.004", source: file:///android_asset/www/vendors.js (8)
02-10 08:23:36.010 12206-12206/io.cozy.drive.mobile D/SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 8 : console.groupEnd
02-10 08:23:36.010 12206-12206/io.cozy.drive.mobile I/chromium: [INFO:CONSOLE(8)] "console.groupEnd", source: file:///android_asset/www/vendors.js (8)
02-10 08:23:36.064 12206-12206/io.cozy.drive.mobile W/zygote: Attempt to remove non-JNI local reference, dumping thread
02-10 08:23:40.732 2320-12300/com.google.android.gms.persistent W/ctxmgr: [AclManager]No 2 for (accnt=account#-517948760#, com.google.android.gms(10013):IndoorOutdoorProducer, vrsn=13280000, 0, 3pPkg = null ,  3pMdlId = null ,  pid = 2320). Was: 3 for 57, account#-517948760#
02-10 08:23:40.950 1692-1706/system_process I/UsageStatsService: User[0] Flushing usage stats to disk
02-10 08:23:45.736 2320-12300/com.google.android.gms.persistent W/ctxmgr: [AclManager]No 2 for (accnt=account#-517948760#, com.google.android.gms(10013):IndoorOutdoorProducer, vrsn=13280000, 0, 3pPkg = null ,  3pMdlId = null ,  pid = 2320). Was: 3 for 57, account#-517948760#
02-10 08:23:50.735 2320-12120/com.google.android.gms.persistent W/ctxmgr: [AclManager]No 2 for (accnt=account#-517948760#, com.google.android.gms(10013):IndoorOutdoorProducer, vrsn=13280000, 0, 3pPkg = null ,  3pMdlId = null ,  pid = 2320). Was: 3 for 57, account#-517948760#
02-10 08:23:55.736 2320-12300/com.google.android.gms.persistent W/ctxmgr: [AclManager]No 2 for (accnt=account#-517948760#, com.google.android.gms(10013):IndoorOutdoorProducer, vrsn=13280000, 0, 3pPkg = null ,  3pMdlId = null ,  pid = 2320). Was: 3 for 57, account#-517948760#
02-10 08:24:00.005 1692-1706/system_process E/memtrack: Couldn't load memtrack module
02-10 08:24:00.005 1692-1706/system_process W/android.os.Debug: failed to get memory consumption info: -1
02-10 08:24:00.014 1692-1706/system_process E/memtrack: Couldn't load memtrack module
02-10 08:24:00.014 1692-1706/system_process W/android.os.Debug: failed to get memory consumption info: -1
02-10 08:24:00.025 1443-1466/? D/hwcomposer: hw_composer sent 24 syncs in 87s

Voici la partie nginx qui me paraît intéressante :

server {
    listen 443 ssl;
    ssl_certificate /etc/letsencrypt/live/educappli.fr/fullchain.pem; # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/educappli.fr/privkey.pem; # managed by Certbot
    include /etc/letsencrypt/options-ssl-nginx.conf; # managed by Certbot
    ssl_dhparam /etc/letsencrypt/ssl-dhparams.pem; # managed by Certbot

server_name mon_nom_de_serveur; # managed by Certbot

    add_header Strict-Transport-Security max-age=2678400;

    location / {
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header Host $http_host;
        proxy_pass http://cozy;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
    }

    access_log /var/log/nginx/cozy.log;

}

Et voici les logs du nginx qui reçoit un timeout du serveur cozy :

2019/02/10 08:52:10 [error] 1350#1350: *8409 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.1.109, server: photos.fred.educappli.fr, request: “GET /files/fsck HTTP/1.1”, upstream: “http://127.0.0.1:8080/files/fsck”, host: “fred.educappli.fr

J’ai mis quelques logs de debug de cozy-stack :

2019/02/10 08:52:10 [error] 1350#1350: *8409 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.1.109, server: photos.fred.educappli.fr, request: "GET /files/fsck HTTP/1.1", upstream: "http://127.0.0.1:8080/files/fsck", host: "fred.educappli.fr" 
time="2019-02-10T09:05:17+01:00" level=debug msg="response: {\"total_rows\":2370,\"offset\":2300,\"rows\":[\r\n{\"id\":....TRES_LONGUE_LIGNE
time="2019-02-10T09:06:43+01:00" level=debug msg="request: GET global%2Fconfigs/assets " domain="<unknown>" nspace=couchdb
time="2019-02-10T09:06:43+01:00" level=debug msg="CouchDB(not_found): Database does not exist." domain="<unknown>" nspace=couchdb
time="2019-02-10T09:08:43+01:00" level=debug msg="request: GET global%2Fconfigs/assets " domain="<unknown>" nspace=couchdb
time="2019-02-10T09:08:43+01:00" level=debug msg="CouchDB(not_found): Database does not exist." domain="<unknown>" nspace=couchdb

Y aurait-il une erreur dans la configuration de nginx ou ailleurs ?

Merci.


#42

J’ai trouvé le problème, en tout cas en ce qui me concerne.

J’ai fait du remote debugging sur cozy-stack et j’ai constaté que le processus fonctionnait correctement mais qu’il mettait beaucoup de temps, en tout cas plus que le temps que nginx met à retourner l’erreur 504.

Du coup, j’ai ajouté ceci dans la config nginx dans le bloc location et pour moi cela fonctionne maintenant :

proxy_connect_timeout       6000;
proxy_send_timeout          6000;
proxy_read_timeout          6000;
send_timeout                6000;

Le timeout est un peu élevé maintenant, je pense que je peux le diminuer :slight_smile:


#43

De mon côté, je n’ai pas l’impression que cela a fonctionné, mais vu le temps que j’y ai passé, j’ai probablement zappé un truc dans la config.

@dohseven : de ton côté tu as pu tester ça ?

@fensminger : lors de ton debugging, as tu pu identifier quelle requête prenait particulièrement du temps ? Et comment as tu mesur& le temps de réponse de cozy stack ? Je voudrais pouvoir répéter ça chez moi pour m’assurer que c’est bien le soucis que je rencontre


#44

@cpique Pareil que toi, en ajoutant juste les timeouts à la config Nginx, ça ne règle pas le souci pour moi : je n’ai plus d’erreurs Nginx avec ces modifications, par contre j’ai toujours des erreurs HTTP 499 sur les POSTs des photos vers la stack Cozy.

Par contre je n’ai pas pris le temps de tester correctement, j’ai fait ça en 5 minutes, il faut que je m’y mette un peu plus sérieusement pour pouvoir faire un retour complet.


#45

C’est la méthode ci-dessous du fichier files.go qui met beaucoup de temps chez moi. Je n’ai pas analysé le détail, mais en mettant un point d’arrêt au début et à la fin, cela met chez moi plusieurs minutes. Vu son nom, cela ne m’étonne pas beaucoup si on commence à avoir de nombreux fichiers.

func fsckHandler(c echo.Context) error {
...
}

#46

Pour l’erreur 499, il s’agit du client qui a fermé la connexion avant de recevoir la réponse. Cette erreur se produit quand le traitement est trop long côté serveur (source https://fr.wikipedia.org/wiki/Liste_des_codes_HTTP#cite_note-16).

C’est du coup certainement le cozy-drive sur ton téléphone qui a fermé la connexion car cela était trop long ou le système android (mais je n’y crois pas trop).

Peut-être as-tu beaucoup plus de fichiers que moi, car moi je débute avec cozy cloud et je n’ai pas des dizaines de milliers de photos.


#47

J’ai de l’ordre de 20Go de photos synchronisées depus mon PC (source appareil photo)

@Clochix : je ne sais pas qui chez cozy peut nous aider à déterminer que c’est bien le FS check qui fait planter la synchro.
@Aeris : sur votre infra, les timeout du RP sont sur quel ordre de grandeur ?


#48

@cpique On a regardé rapidement le code ce matin.
Le problème sur l’auto-hébergement est qu’il n’y a aucun cache, puisque pas de redis…
Du coup le fsck se déclenche sur chaque requête, là où sur notre infra il ne se déclenche que tous les 3 mois…

On regarde en interne si et comment on peut corriger ça.


#49

@aeris Merci pour les infos. Pour ma part, j’ai vu dans le cozy.yaml la possibilité de paramétrer un serveur redis. Je vais donc essayer de paramétrer le serveur de cache. Est-ce que vous avez un conseil sur les paramètres du serveur pour un petit serveur personnel avec 8Go de RAM ? Je vais déjà prendre une image docker redis 32bits pour consommer moins de mémoire.


#50

@fensminger malheureux, mettre æ. et le mot D***** dans la même phrase, tu veux donc provoquer une apocalypse ? (plus sérieusement, prend garde, une très sérieuse faille de sécurité a touché Docker cette semaine, veille à mettre à jour ton système).


#51

Bonjour,
j’ai aussi le même problème depuis que j’ai mis à jour mon cozy le 30 novembre 2018.
L’appli synchronise mes photos, mais rien n’apparaît sur le serveur. (et à l’ouverture suivante l’appli renvoit les photos, mais toujours rien).

D’après mon etckeeper, il semble que c’est depuis ces mises à jours :
Package changes:
-cozy 2018M4S3-1 all
-cozy-coclyco 0.2.3-1 all
+cozy 2:1.0.0-1 all
+cozy-coclyco 0.3.0-1 all
-cozy-stack 2018M4S3-1 amd64
+cozy-stack 2:1.0.0-1 amd64

j’ai rajouté les timeouts dans nginx comme @fensminger l’a proposé, mais pas de différence.

Sinon, la partie “Collect” fonctionne comme un charme :slight_smile:


#52

Bonjour @rico,

Bienvenue sur ce forum :slight_smile:

J’avoue que pour l’instant nous séchons complètement sur ce souci.

@aeris a-t-on du nouveau pour le fsck ?


#53

En l’état non, pas de nouvelles, et sans redis il faudrait envisager un cache en mémoire côté stack :sob:


#54

Correction, ça a été implémenté dans la dernière version livrée ce lundi du coup :blush:


#55

Arf, je viens de faire la mise à jour :
Package changes:
-cozy 2:1.2.1-1 all
+cozy 2:1.2.2-1 all
-cozy-stack 2:1.2.1-1 amd64
+cozy-stack 2:1.2.2-1 amd64
(et redémarré)

Et après une synchro, les photos n’apparaissent toujours pas dans le drive :cry:

02-27 15:38:24.751  7567 10123 W System.err: java.net.SocketTimeoutException: timeout
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:616)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:624)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http2.Http2Stream.takeResponseHeaders(Http2Stream.java:146)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:127)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:61)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
02-27 15:38:24.751  7567 10123 W System.err: 	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
02-27 15:38:24.752  7567 10123 W System.err: 	at okhttp3.RealCall.execute(RealCall.java:77)
02-27 15:38:24.752  7567 10123 W System.err: 	at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:400)
02-27 15:38:24.752  7567 10123 W System.err: 	at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:279)
02-27 15:38:24.752  7567 10123 W System.err: 	at android.os.AsyncTask$2.call(AsyncTask.java:305)
02-27 15:38:24.752  7567 10123 W System.err: 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
02-27 15:38:24.752  7567 10123 W System.err: 	at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:243)
02-27 15:38:24.752  7567 10123 W System.err: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
02-27 15:38:24.752  7567 10123 W System.err: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
02-27 15:38:24.752  7567 10123 W System.err: 	at java.lang.Thread.run(Thread.java:761)
02-27 15:38:24.779  7567  7567 D SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 33 : startMediaBackup upload item error
02-27 15:38:24.779  7567  7567 I chromium: [INFO:CONSOLE(33)] "startMediaBackup upload item error", source: file:///android_asset/www/vendors.js (33)
02-27 15:38:24.781  7567  7567 D SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 33 : {"code":-1,"source":"/storage/9353-A196/DCIM/Camera/IMG_20190216_120605.jpg","target":"https://cozy.sorico.fr/files/8c906d18ca124c270ac0b14da009d3bc?Name=IMG_20190216_120605.jpg&Type=file&Tags=library&Executable=false","message":"java.net.SocketTimeoutException: timeout"}
02-27 15:38:24.781  7567  7567 I chromium: [INFO:CONSOLE(33)] "{"code":-1,"source":"/storage/9353-A196/DCIM/Camera/IMG_20190216_120605.jpg","target":"https://cozy.sorico.fr/files/8c906d18ca124c270ac0b14da009d3bc?Name=IMG_20190216_120605.jpg&Type=file&Tags=library&Executable=false","message":"java.net.SocketTimeoutException: timeout"}", source: file:///android_asset/www/vendors.js (33)
02-27 15:38:24.782  7567  7567 D SystemWebChromeClient: file:///android_asset/www/vendors.js: Line 33 : {"id":1173,"fileName":"IMG_20190216_120605.jpg","width":3264,"height":2448,"libraryId":"-1944405919","creationDate":"2019-02-16T12:06:05.942Z","filePath":"/storage/9353-A196/DCIM/Camera/IMG_20190216_120605.jpg","mimeType":"image/jpeg"}

#56

Ça vient d’autre part peut-être du coup… :thinking::sob:


#57

Du coup ca fonctionne comment ?
Quand fsck se lance, il écrit en mémoire (RAM ? DD ?) pour éviter une relance du process.

Mais si @rico a redémarré le serveur peut être que le cache ne s’est pas encore construit ?

J’essaie d’avoir un peu d’espoir :disappointed_relieved:


#58

Oui c’est ça, on stocke en RAM l’info pour éviter d’avoir à recalculer le truc.


#59

D’ailleurs, un truc bizarre :
il y a 2 jours, j’ai ré-essayé une synchro des photos après avoir fait une mise à jour, et une 60aine de photos se sont synchronisées hyper rapidement, nickel !
Tout en joie, j’ai voulu vérifier si elles était bien toutes passées : j’ai fermé l’appli, réouvert, il m’a dit qu’il restait encore 10 photos… Et ça ne fonctionnait plus… les 10 photos restantes ne se sont pas synchronisées…
Je n’y comprend rien.


#60

@dohseven @cpique
D’après vos logs (logcat et access logs de Nginx) vous êtes en HTTP/2.0. Perso, je viens de vérifier dans mes access logs Nginx, tout est en HTTP/1.0 ou 1.1, je n’ai aucune requête en HTTP/2.0.
Est-ce que vous pouvez confirmer que vous avez configurés Nginx pour faire du HTTP/2.0 ? (a priori, il suffit d’ajouter http2 à la directive listen)
Si c’est bien le cas, pouvez-vous refaire un test en supprimant la conf HTTP/2.0 de Nginx ?

Je vais essayer de trouver un peu de temps ce week-end pour passer en HTTP/2.0 sur mon Nginx et faire des tests depuis l’appli mobile.

Avez-vous un compte sur la version hébergée de Cozy (mycozy.cloud) ? Si oui, avez-vous le même soucis de sauvegarde des photos avec votre instance mycozy.cloud ?

@dohseven
Je suppose que le RST_STREAM que tu vois passer dans les logs Nginx correspond au timeout vu avec adb logcat. Si tu peux confirmer que tu vois bien apparaitre les deux en même temps…

Petite question pour l’équipe Cozy : vous savez à combien est réglé le timeout côté appli mobile ?

Sinon comme ça, je ferais un bon gros tcpdump pour capturer tout le trafic réseau (et pas que le 8080).
Du genre tcpdump -pni any -s0 -w/tmp/foobar.pcap, et ensuite tu ouvres ce fichier avec Wireshark et tu fouilles… Tu verras peut-être passer le fameux POST pour l’upload de la photo sur le port 8080, mais pas sa réponse.

Généralement, les applis log les requêtes une fois qu’elles sont traitées (il me semble que c’est le cas de Nginx, peut-être est-ce la même chose pour cozy-stack). Du coup, tu ne vois passer le POST dans les logs uniquement lorsque la réponse est renvoyée … mais si la réponse met beaucoup de temps à être envoyée, tu peux avoir le log que bien plus tard (c’est trompeur comme comportement). D’où l’intérêt de la capture réseau qui te montrera si le POST est réellement passé de Nginx vers cozy-stack.