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: