App remains blocked in cleaning up deleted items mode

[bnjbvr]

It seems that when I'm deleting an article locally, and then runs a sync, the app enters the "clean up deleted articles" mode, and then never leaves it. The android notification stays open, with a loading bar that remains filled at around 20%. This prevents subsequent synchronizations, including fetching new articles stored on the server, read markers sync, and then the only way to escape this mode seems to require disconnecting and reconnecting to the instance and account.

Duplicate?

Have you searched the issues of this repository if your issue is already known? Only first page

Environment details

• wallabag app version: 2.3.0
• wallabag app installation source (e.g. Gplay, F-Droid, manual): gplay
• Android OS version: 9
• Android ROM (e.g. stock, LineageOS, SlimRom,…): Samsung stock
• Android hardware: galaxy s 8, galaxy tab s6
• wallabag server version: 2.8.3
• Do you have Two-Factor-Authentication enabled?: no

Logs

wallabag server

Please paste relevant wallabag server logs here (from file <wallabag>/var/logs/prod.log):

Web server

Please paste relevant web server logs (e.g. from nginx, Apache, …) here:

NOTE: Be super sure to remove sensitive data like passwords, note that everybody can look here!

Your experience with wallabag Android app

Have you had any luck using wallabag Android app before? (Sometimes we get tired of reading bug reports all day and a lil' positive end note does wonders)

It's been wonderful so far, happily replaced pocket with wallabag three years ago and still not a single regret.

[di72nn]

What does the notification say?

You listed two Android devices: are you experiencing the same problem on more than one device?

Also, let me clarify: the sync you're talking about happens automatically after deletion, not invoked manually, right?

[bnjbvr]

What does the notification say?

In French, it says something like "cleaning up deleted articles".

You listed two Android devices: are you experiencing the same problem on more than one device?

Yes.

Also, let me clarify: the sync you're talking about happens automatically after deletion, not invoked manually, right?

I would need to check next time it happens, but I relatively am sure of myself, so yes.

[di72nn]

Ok, that's a bit unusual - I don't remember "article sweeping" ever getting stuck.

We'll need logs (logcat output) collected since the start of an update to the moment the app gets stuck. Unfortunately, we still don't have any feature to facilitate logs gathering through the app, so you'll have to use any generic tool for that.

Not yet necessary, but server logs may also be needed: the access log of the web server to see which requests the server received from the app and wallabag log needs to be checked for errors during sync.

[bnjbvr]

I'm seeing this again, so I'd be happy to help diagnose the error a bit better.

First of all, steps to reproduce consist in erasing something on the web app, then doing a sync locally on the android app. It seems the sync may happen automatically, but the android app gets stuck no matter what.

Server logs show only one single error repeated many times, but all the requests somehow still return a 200 http code, so its probably not a blocking error.

2020/04/26 11:56:01 [error] 251#251: *18084 FastCGI sent in stderr: "PHP message: PHP Warning:  "continue" targeting switch is equivalent to "break". Did you mean to use "continue 2"? in /var/www/wallabag/vendor/doctrine/orm/lib/Doctrine/ORM/UnitOfWork.php on line 2636PHP message: PHP Warning:  "continue" targeting switch is equivalent to "break". Did you mean to use "continue 2"? in /var/www/wallabag/vendor/doctrine/orm/lib/Doctrine/ORM/UnitOfWork.php on line 2665" while reading response header from upstream, client: 172.19.0.22, server: _, request: "HEAD /login HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "wallabag.example.com", referrer: "https://wallabag.example.com/"

What generic tool for capturing log output would be appropriate?

[di72nn]

You can try this.

[di72nn]

You can also use "Settings -> Miscellaneous -> Save logcat output to a file" in our latest beta (available in releases or opt-in in google play).

[anarcat]

I also have this problem that the "Sweeping deleting articles" seem to hang. It actually is just extremely slow: I have gotten used to the app just being permanently in a notification, as the sweep takes about 10-20 minutes every time. So whenever I open the app, it just sits there doing essentially nothing (from a user's perspective of course!) for a long time...

I wonder if that is what might be happening to this user?

[di72nn]

That's quite possible.

BTW, "sweeping after sync" is a somewhat niche option: if you don't delete articles from different devices all the time, you probable don't need it enabled (you can run the sweeping manually once in a while).

[bnjbvr]

Hi there! I retried with the new beta, and at least now it fails quickly with an error.

Backtrace

Erreur inconnue
okhttp3.internal.http2.StreamResetException: stream was reset: CANCEL
Pile d'erreur :
okhttp3.internal.http2.StreamResetException: stream was reset: CANCEL
	at okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148)
	at okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:96)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at wallabag.apiwrapper.TokenRefreshingInterceptor.intercept(TokenRefreshingInterceptor.java:65)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:197)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:148)
	at retrofit2.OkHttpCall.execute(OkHttpCall.java:188)
	at retrofit2.DefaultCallAdapterFactory$ExecutorCallbackCall.execute(DefaultCallAdapterFactory.java:104)
	at wallabag.apiwrapper.WallabagService.execAndCheckBody(WallabagService.java:1499)
	at wallabag.apiwrapper.WallabagService.articlesExistByUrls(WallabagService.java:505)
	at wallabag.apiwrapper.BatchExistQueryBuilder.execute(BatchExistQueryBuilder.java:271)
	at fr.gaulupeau.apps.Poche.service.workers.DeletedArticleSweeper.performSweep(DeletedArticleSweeper.java:215)
	at fr.gaulupeau.apps.Poche.service.workers.DeletedArticleSweeper.sweepDeletedArticles(DeletedArticleSweeper.java:79)
	at fr.gaulupeau.apps.Poche.service.workers.DeletedArticleSweeper.sweep(DeletedArticleSweeper.java:56)
	at fr.gaulupeau.apps.Poche.service.tasks.SweepDeletedArticlesTask.run(SweepDeletedArticlesTask.java:17)
	at fr.gaulupeau.apps.Poche.service.tasks.ActionRequestTask.run(ActionRequestTask.java:25)
	at fr.gaulupeau.apps.Poche.service.-$$Lambda$Eg7UQkyPgCNRHvigqxzb-ridugA.run(Unknown Source:2)
	at fr.gaulupeau.apps.Poche.service.TaskService.run(TaskService.java:158)
	at fr.gaulupeau.apps.Poche.service.TaskService.lambda$gjfracnqY8x0_-mrxsx0oqjQmgk(Unknown Source:0)
	at fr.gaulupeau.apps.Poche.service.-$$Lambda$TaskService$gjfracnqY8x0_-mrxsx0oqjQmgk.run(Unknown Source:2)
	at java.lang.Thread.run(Thread.java:764)
	Suppressed: okhttp3.internal.http2.StreamResetException: stream was reset: CANCEL
		... 32 more

Full logcat is here, shared for a week.

Just to make sure we're on the same page: I'm not using the sync mode that automatically sweeps during sync; I'm doing a manual sweep here.

[anarcat]

BTW, "sweeping after sync" is a somewhat niche option: if you don't delete articles from different devices all the time, you probable don't need it enabled (you can run the sweeping manually once in a while).

Yeah, I do use multiple devices and somewhat frequently delete articles. But I guess I could trigger the sweep manually... how is that done, is that the "Full update" button?

[di72nn]

@bnjbvr this doesn't seem like a client issue. You probably need to check server logs (wallabag's log and the log of your HTTP-server).

@anarcat there's a "sweep deleted articles" option in the three-dot-menu on the main screen.

[bnjbvr]

@bnjbvr this doesn't seem like a client issue. You probably need to check server logs (wallabag's log and the log of your HTTP-server).

Yeah, i did this: the php app server's logs didn't show anything wrong, and the nginx reverse proxy just showed that the first request ended correctly (with 200), and then the next ones were incorrect. It seems there's a streaming request sent from the app, and the server considers it done after the first result is streamed back from the server to the android app, while the android app expects other results to come...

[di72nn]

the first request ended correctly (with 200)

Do you mean the initial sync?

Can you disable "auto-sync on application start" (Settings - Synchronization), completely kill the app, launch the app and start sweeping? I'd like to make sure that's not an issue with connection pooling.

[bnjbvr]

Do you mean the initial sync?

Oops, no sorry, I meant that i saw in the logs that there were requests sent to ask the server whether each article exists on the server, based on the URL. The app seems to ask this information in batches, and the request for the first batch did succeed, and then subsequent requests were the one failing.

[di72nn]

That's weird, considering that the very first exists request fails (so from app's point of view there were no successful exists responses).

These exists requests are a bit unusual in that they have to use HTTP GET with a large query. Can you check what's your web server's "request line"/"request header" max size? The app currently makes requests a bit under 8 kilobytes.

[bnjbvr]

I tried bumping client_header_buffer_size to 64K and large_client_header_buffers to 4 64K in nginx's configuration and restart, but this made no difference.

At this point, my best guess is that it's either a bug in Nginx or in the HTTP library OkHttp, or an Nginx misconfiguration (missing proxy command). It's a bit weird because websockets and other streamed connections seem to work fine for every other service I'm hosting that use those, so not sure what could be wrong here.

If that's not too much trouble, would it be possible to bump the version of okhttp in the beta version? Or just build it and provide me with an APK i could try?
If you wanted to try it by yourself, let me know and i can send you an invite link to my instance.

Thanks for all the work and taking the time to investigate! This is really a minor issue, and as far as I can tell, the beta version allows me to do a full sync without any issues now, resulting in the same effect but slower. The non-beta version had the same bug with the full sync, for what it's worth.

[di72nn]

@bnjbvr any change with the latest release/beta (2.4.0 is available on Google Play, 2.4.0-beta.6 (no code changes compared to the release) in F-Droid)?

[bnjbvr]

Nope, this is still happening on both my devices.

[di72nn]

wallabag app version: 2.4.2, master.
Server: wallabag.it (nginx/1.14.2).

Reproducible with query length >= 5653, fine with 5594 (didn't test values in-between).