Sauvegarde des photos depuis Cozy Drive ne fonctionne plus


#21

J’ai tenté de regarder dans les logs détaillés de nginx, et la fermeture côté client semble être intentionnelle :

2018/10/06 18:06:19 [debug] 22532#22532: *734110 process http2 frame type:3 f:0 l:4 sid:3
2018/10/06 18:06:19 [debug] 22532#22532: *734110 http2 RST_STREAM frame, sid:3 status:8
2018/10/06 18:06:19 [info] 22532#22532: *734110 client canceled stream 3, client: 82.64.xx.yyy, server: *.mon.cozy.chez.moi, request: "POST /files/e0fa5d21560802d3b619aaa494044f93?Name=20180903_182106.jpg&Type=file&Tags=library&Executable=false HTTP/2.0", host: "mon.cozy.chez.moi"
2018/10/06 18:06:19 [debug] 22532#22532: *734110 http run request: "/files/e0fa5d21560802d3b619aaa494044f93?Name=20180903_182106.jpg&Type=file&Tags=library&Executable=false"
2018/10/06 18:06:19 [debug] 22532#22532: *734110 http2 read client request body handler
2018/10/06 18:06:19 [info] 22532#22532: *734110 client prematurely closed stream, client: 82.64.xx.yyy, server: *.mon.cozy.chez.moi, request: "POST /files/e0fa5d21560802d3b619aaa494044f93?Name=20180903_182106.jpg&Type=file&Tags=library&Executable=false HTTP/2.0", host: "mon.cozy.chez.moi"
2018/10/06 18:06:19 [debug] 22532#22532: *734110 http finalize request: 499, "/files/e0fa5d21560802d3b619aaa494044f93?Name=20180903_182106.jpg&Type=file&Tags=library&Executable=false" a:1, c:1
2

Nginx reçoit une trame HTTP2 RST_STREAM, et si j’en crois la RFC, dans ce cas-là le client demande explicitement la déconnexion et la coupure du flux. Et selon les logs, le client dans ce cas-là semble bien être l’appli Cozy Drive, puisque l’IP correspond au point d’accès où est connecté mon smartphone en Wifi.

J’ai essayé de comparer avec l’envoi d’un document qui fonctionne, et dans ce cas-là j’ai une trame HTTP2 DATA qui arrive et qui déclenche le début de l’envoi :

2018/10/06 18:42:21 [debug] 22533#22533: *734639 http2 DATA frame
2018/10/06 18:42:21 [debug] 22533#22533: *734639 event timer del: 3: 1538844196952
2018/10/06 18:42:21 [debug] 22533#22533: *734639 event timer add: 3: 60000:1538844201387
2018/10/06 18:42:21 [debug] 22533#22533: *734639 http body new buf t:1 f:0 000055A83D6084D9, pos 000055A83D6084D9, size: 2852 file: 0, size: 0
2018/10/06 18:42:21 [debug] 22533#22533: *734639 http write client request body, bufs 000055A83D47CF00
2018/10/06 18:42:21 [debug] 22533#22533: *734639 add cleanup: 000055A83D3F8480
2018/10/06 18:42:21 [debug] 22533#22533: *734639 hashed path: /var/lib/nginx/body/0000048976
2018/10/06 18:42:21 [debug] 22533#22533: *734639 temp fd:4
2018/10/06 18:42:21 [warn] 22533#22533: *734639 a client request body is buffered to a temporary file /var/lib/nginx/body/0000048976, client: 82.64.xx.yyy, server: *.mon.cozy.chez.moi, request: "POST /files/io.cozy.files.root-dir?Name=095587-an-01-fr-balance_cuis.pdf&Type=file&Executable=false HTTP/2.0", host: "mon.cozy.chez.moi"

Il semblerait donc que le problème vienne bien du client, où d’un truc en amont de nginx, mais là j’avoue que j’arrive aux limites de mes compétences…
Peut-être que @cpique aura plus d’infos dans ses logs !


#22

Merci beaucoup pour tous ces détails @dohseven,

J’invoque à présent les Experts Mobile ( @y_lohse @_Crash ). Mais je ne comprend pas, nous n’avons pas ce souci sur nos serveurs.

Yannick et Quentin, comment pourrions-nous récupérer les journaux de son appli mobile ?


#23

Salut !

Comme ça, je ne vois pas ce qui pourrait fermer la connexion de manière intentionnelle ! Un peu de log côté Client va peut-être nous être utile. Je l’espère

Pour cela, il faut installer adb.
Une fois adb installé, il faut connecter son téléphone en USB sur l’ordi, et logiquement en faisant un adb logcat vous devriez avoir accès aux journaux live du téléphone. Donc si vous lancez une synchro, vous devriez voir des entrées arriver.

S’il y a trop d’entrées confuses (vu que logcat est global au téléphone), un truc du style :
adb -d logcat io.cozy.drive.mobile:I *:S ne devrait faire ressortir que ce qui est propre à l’application Cozy.

Si rien n’apparait dans les logs, alors je vous ferais une build avec des logs un peu partout pour voir ce qui peut se passer.


#24

Hello @_Crash !

Merci pour les instructions.

J’ai pris un log complet avec adb logcat, et lors de la sauvegarde de Cozy Drive je vois apparaître pour chaque photo un timeout du type :

W/System.err(15781): java.net.SocketTimeoutException: timeout
W/System.err(15781): 	at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:616)
W/System.err(15781): 	at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:624)
W/System.err(15781): 	at okhttp3.internal.http2.Http2Stream.takeResponseHeaders(Http2Stream.java:146)
W/System.err(15781): 	at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:127)
W/System.err(15781): 	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:61)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W/System.err(15781): 	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W/System.err(15781): 	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W/System.err(15781): 	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W/System.err(15781): 	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W/System.err(15781): 	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W/System.err(15781): 	at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
W/System.err(15781): 	at okhttp3.RealCall.execute(RealCall.java:77)
W/System.err(15781): 	at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:388)
W/System.err(15781): 	at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:279)
W/System.err(15781): 	at android.os.AsyncTask$2.call(AsyncTask.java:288)
W/System.err(15781): 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
W/System.err(15781): 	at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
W/System.err(15781): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/System.err(15781): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/System.err(15781): 	at java.lang.Thread.run(Thread.java:818)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : startMediaBackup upload item error
I/chromium(15781): [INFO:CONSOLE(66)] "startMediaBackup upload item error", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : {"code":-1,"source":"/storage/emulated/0/DCIM/Camera/20180831_165140.jpg","target":"https://mon.cozy.chez.moi/files/e0fa5d21560802d3b619aaa494044f93?Name=20180831_165140.jpg&Type=file&Tags=library&Executable=false","message":"java.net.SocketTimeoutException: timeout"}
I/chromium(15781): [INFO:CONSOLE(66)] "{"code":-1,"source":"/storage/emulated/0/DCIM/Camera/20180831_165140.jpg","target":"https://mon.cozy.chez.moi/files/e0fa5d21560802d3b619aaa494044f93?Name=20180831_165140.jpg&Type=file&Tags=library&Executable=false","message":"java.net.SocketTimeoutException: timeout"}", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : {"id":235630,"fileName":"20180831_165140.jpg","width":4160,"height":2340,"libraryId":"-1739773001","creationDate":"2018-08-31T16:24:18.500Z","filePath":"/storage/emulated/0/DCIM/Camera/20180831_165140.jpg","mimeType":"image/jpeg"}
I/chromium(15781): [INFO:CONSOLE(66)] "{"id":235630,"fileName":"20180831_165140.jpg","width":4160,"height":2340,"libraryId":"-1739773001","creationDate":"2018-08-31T16:24:18.500Z","filePath":"/storage/emulated/0/DCIM/Camera/20180831_165140.jpg","mimeType":"image/jpeg"}", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : Raven is recording exception
I/chromium(15781): [INFO:CONSOLE(66)] "Raven is recording exception", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : Backup error: java.net.SocketTimeoutException: timeout
I/chromium(15781): [INFO:CONSOLE(66)] "Backup error: java.net.SocketTimeoutException: timeout", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : %c action %cCURRENT_UPLOAD %c@ 16:42:40.542
I/chromium(15781): [INFO:CONSOLE(66)] "%c action %cCURRENT_UPLOAD %c@ 16:42:40.542", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : console.groupEnd
I/chromium(15781): [INFO:CONSOLE(66)] "console.groupEnd", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)
D/SystemWebChromeClient(15781): file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js: Line 66 : ListLibraryItems plugin: calling uploadItem...
I/chromium(15781): [INFO:CONSOLE(66)] "ListLibraryItems plugin: calling uploadItem...", source: file:///android_asset/www/app.8983bbe4caa9b5602c10.min.js (66)

J’espère que ça pourra vous aider !


#25

J’ai également le même log :

W System.err: at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:616)
W System.err: at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:624)
W System.err: at okhttp3.internal.http2.Http2Stream.takeResponseHeaders(Http2Stream.java:146)
W System.err: at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:127)
W System.err: at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:61)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W System.err: at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W System.err: at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W System.err: at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W System.err: at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
W System.err: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
W System.err: at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
W System.err: at okhttp3.RealCall.execute(RealCall.java:77)
W System.err: at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:388)
W System.err: at io.cozy.plugins.listlibraryitems.ListLibraryItems$UploadFileTask.doInBackground(ListLibraryItems.java:279)
W System.err: at android.os.AsyncTask$2.call(AsyncTask.java:304)
W System.err: at java.util.concurrent.FutureTask.run(FutureTask.java:237)
W System.err: at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:243)
W System.err: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
W System.err: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
W System.err: at java.lang.Thread.run(Thread.java:762)

#26

Merci @cpique,

Donc côté client on voit un timeout, et côté serveur on a l’impression que c’est le client qui ferme la connexion.

@nono tu aurais une idée ? La piste http2 est tentante, mais que faire ?


#27

Des nouvelles sur ce sujet ?


#28

Perso je n’ai pas continué à creuser, je ne vois pas trop où continuer :man_shrugging:


#29

Rien de notre côté malheureusement, nous sommes en panne d’idée.


#30

Bonjour a tous,

je viens de lire le post en diagonal car j’ai le même soucis … Je vais tout lire pour etre sur que la solution n’a pas été indiquer plus haut mais sur les dernier partage ça ne semblait pas résolu.


#31

Hello @gudbes,

Non, malheureusement nous ne comprenons pas ce qui se passe et nous n’avons pas d’idée pour analyser plus en détail le souci.


#32

Salut @Clochix,

Je comprend qu’il soit compliqué de travailler sur tous les fronts :pensive:. Malheureusement je trouve la partie auto hébergé de cozy en voix d’extinction… Les soucis et les améliorations pour les auto hébergé n’ont pas le temps d’être traiter par la cozy team qui travaille déjà à 300% sur la partie “payante” du projet. Pour assurer la stabilité de mes données, je vais (à contre cœur) essayé (mais je reviendrais peut être) d’autres solutions plus stables qui correspondent à mon cas (auto hébergé). Si je trouve chaussure à mon pied… Je profite dès maintenant de remercier la cozy team pour tout ce qu’elle a fait pour moi et surtout toi @Clochix et @aeris (mes chouchous !) pour m’avoir énormément appris et m’avoir sauver de nombreuses fois de difficultés insurmontables !

Bonne continuation et à très vite je l’espère !


#33

Ce qui avait été évoqué à un moment par _Crash peut il être mis en place ?

Si rien n’apparait dans les logs, alors je vous ferais une build avec des logs un peu partout pour voir ce qui peut se passer.


#34

ping @_Crash ,

je ne sais pas si dans votre processus de développement vous avez quelque chose comme des #IFDEF qui permettrait d’avoir facilement une version très verbeuse de l’application. Au delà de ce cas précis, ça pourrait être utile pour d’autres situations telles que celle évoquées ce matin.


#35

Une autre solution serait une capture réseau intégrale, via du tcpdump/wireshark.
Ça resterait cependant assez bordélique à analyser vu qu’il y a du TLS partout… :fearful:


#36

Je me permet à nouveau un petit up :
Peut on avoir une application verbeuse en terme de logs (quitte à ce que ces logs balancent directement dans un fichier à part pour se simplifier la vie par rapport aux logcat)

Quelle sont les requêtes faites lors de la synchro des photos ?
Et notamment le détail de la requête post pour que j’essaie de reproduire unitairement cette requête.


#37

Hello @cpique,

@_Crash a préparé un APK en mode debug : https://crash-drive.mycozy.cloud/public?sharecode=eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzaGFyZSIsImlhdCI6MTU0ODYwMjE2NywiaXNzIjoiY3Jhc2gubXljb3p5LmNsb3VkIiwic3ViIjoiZW1haWwifQ.a_jrfV6TE6SnaAntNBRbdNo8HGABCI032O184kobTreodpkxQ6zqotT_BQQVhf0T8KM1Z0hLISTSlyIm4duYHA&id=ee5f9cb9c3404cc091917b0d0d757931

De notre côté, nous avions justement prévu ces jours-ci de faire des tests avec HTTP/2 pour voir si le souci pouvait être de ce côté.


#38

Bonjour,

Je suis très intéressé par ce topic, car j’ai le même problème .

Les logs commence à partir de l’authentification à mon cozy-drive.
L’application tente de faire une mise à jour et après quelques minutes, il me dis que je dois être connecté au WIFI. Hors je suis en wifi.
Je suis donc aller dans les paramètres et j’ai lancé 3 synchronisation manuel. En commençant les logs par la fin on voit bien qu’il y a un abondon. (Qui est à l’origine de l’abondon ?)

Le fichier de logs peut-être téléchargé ici.
https://drive.fred.educappli.fr/public?sharecode=08eX3rTA3tdh

J’espère que cela pourra aider.

Frédéric.


#39

Salut,

pour les utilisateurs d’android Nougat, ce message sur stackoverflow suggère de passer l’application en « non optimisé » dans les réglages de la batterie pour régler des problèmes réseau : https://stackoverflow.com/questions/41439830/android-7-1-1-nougat-app-standby-and-network. J’imagine que ça peut valoir le coup d’essayer, vu que ça ne coûte pas grand chose.


#40

Merci, mais on fait quoi pour les utilisateurs des versions Android précédentes ? Je suis en 5.0.2 perso.

Je suis toujours bloqué par ce problème, et ça me paraît étrange qu’il faille changer des choses côté Android alors que la synchro fonctionnait à un moment. C’est donc qu’il y a eu un changement quelque part côté Cozy qui a modifié le bon fonctionnement de la synchro. Trouver lequel, c’est plus compliqué, je suis d’accord…

En tout cas je suis toujours dispo si vous avez besoin de plus de logs ou de tests pour identifier ce qui ne va pas !