proton bridge repeatably fetches the same messages over and over

vkuznet commented 1 year ago

Issue tracker is ONLY used for reporting bugs with technical details. "It doesn't work" or new features should be discussed with our customer support. Please use bug report function in Bridge or contact bridge@protonmail.ch.

After recent upgrade of bridge client, v3.0.20, I found that it fetches the same emails over and over if I delete my mail on in my client, e.g. after some time it appears in my mailbox again. Said that, I use multiple devices, such as Android phone, iPad, and run proton bridge on my mac where I use mutt client. My mutt configuration did not change, but the behavior did change after recent upgrade.

Expected Behavior

If mail is fetched from upstream server the proton bridge should not fetch it over and over again if I delete this email in my client application.

Current Behavior

If I delete my email in my local mail client, I see that the same email appears again. My mail client runs a cronjob to fetch emails from proton bridge on periodic basis and there the email is not marked as delete in upstream IMAP server or the mail stays somewhere in local cache of proton bridge.

Possible Solution

Steps to Reproduce

setup proton bridge
fetch and build goimapsync package from https://github.com/vkuznet/goimapsync
run goimapsync with proton bridge credentials
use your mail client, e.g. mutt, and fetch your email, then delete your recently fetched email, repeat step 3 and your email will be fetched again.

Please note, that in previous version of bridge this issue was never pop-up.

Version Information

v3.0.20

Context (Environment)

Detailed Description

I think either cache or concurrency fetching is an issue here. For instance, if email is fetch by one client and is fetched by another later its flag are not properly reset. So far I'm downgrading the proton bridge to previous version to avoid this issue.

Possible Implementation

PrivacyOsint2 commented 1 year ago

I agree

LBeernaertProton commented 1 year ago

Hey @vkuznet thanks for the report, but could you:

Clarify what you mean by fetched messages: Are you referring to a new email that arrives at a certain mailbox or any message that is already present in a mailbox after the account has been configured?
Have you tried removing and adding your account with 3.0.20, if not could you try that and see if the issue still persists? We fixed an issue with could cause local state to go out of sync with Proton state. Unfortunately, the only way to fix this at the moment is remove and re-add the account.

vkuznet commented 1 year ago

Well, the refetch of emails happen when I have fetched email on my laptop, mark it as read, then delete it, and after some time it was fetched again. During this time my phone is also have proton mail client. Therefore, I can't distinguish if the case reflects when multiple devices are accessing the mailbox or not.

Regarding deleting the account I need more details from you:

do I need to open proton bridge (current version 2.3.0, then delete account there, then upgrade to 3.0.20, or
should I upgrade to newer version (I have backup of my current version), and then delete account, and enable it again?

In any case, will my credentials, like IMAP and SMTP passwords, are recreated? If this the case I need to know this up-front to reconfigure these credentials in program I use to fetch emails.

LBeernaertProton commented 1 year ago

@vkuznet either of the options you described will work. Removing and adding the account will reset the current IMAP/SMTP password.

vkuznet commented 1 year ago

@LBeernaertProton , I deleted and added back my account:

using v2.3.0 everything back normal right away
using v3.0.20 ProtonBridge did not even fetch new emails, so it is completely useless

In both cases, I got new credentials which I used in my local setup. According to log I see bunch of errors for v3, e.g.

time="Mar 20 14:14:46.777" level=error msg="Get \"https://mail-api.proton.me/mail/v4/messages/zpYV70HdN8Fw1YaymXvHEt9fWAFT6hUmE-TAWo19bd-u24b09es3yMg1Yjkm1vHiPuvTTzml4JjeKkuOIkomug==\": context canceled, Attempt 1"
time="Mar 20 14:14:46.777" level=error msg="Get \"https://mail-api.proton.me/mail/v4/messages/-_fDBinfF9zFkMvnCCjh1XelDmT7ZIbq98-wa2Yh7Au9kdzKYsy2oN3QN0xFOVxMsvCHtkKuVV1TOsuzPmPj8g==\": context canceled, Attempt 1"

which are followed by 200 OK messages.

Unless I missed something I have no idea what's wrong with new version of bridge, but at this moment it is not working for me as expected, while previous version v2.3.0 is working just fine.

LBeernaertProton commented 1 year ago

@vkuznet there was a minor service outage yesterday around that time. I would recommend trying again today. The errors you are seeing are related to a network timeout cancelling the context of the current request.

vkuznet commented 1 year ago

@LBeernaertProton , I'm not sure that your statement is true. I tried again and got the same behavior. Moreover, I found even more weird stuff. Suddenly, it starts placing so many HTTP calls that I find it very suspicious and kill the process, e.g. in one minute I got this number of HTTP calls

grep "Mar 21 07:42" ~/Library/Application\ Support/protonmail/bridge-v3/logs/v3.0.20_7be46a4740_1679398641.log | grep "200 OK" | wc -l
    2327

grep "Mar 21 07:43" ~/Library/Application\ Support/protonmail/bridge-v3/logs/v3.0.20_7be46a4740_1679398641.log | grep "200 OK" | wc -l
    1239

At this moment I'll stay away from this release.

LBeernaertProton commented 1 year ago

@vkuznet The number of successful HTTP calls is not a good indicator of "suspicious activity". There are many different requests the Bridge performs and it all depends on the user's activity on their account and/or instructions from the Proton servers.

It would be really helpful in diagnosing the issue if we could verify that a clean slate in 3.0.20 is still able to reproduce your issue. I would recommend starting the bridge in CLI mode, log into your account, let the initial data sync finish and then try again. In CLI mode you should see a message which prints the current sync progress.

vkuznet commented 1 year ago

Well, I doubt that 5K HTTP calls within couple of minutes is normal either when there is no user activity, i.e. new emails. Said that, I'll be happy to help if I know instructions how to run CLI mode. Please advise how CLI mode should be run, and how to identify that initial data sync is done.

LBeernaertProton commented 1 year ago

You may have received a refresh event from the Proton servers, which requires us to re-download all your state. This could explain the large number of requests.

I'm assuming that you are using Linux, if not please let me know and I'll provide other binary paths. You can start the bridge in cli mode with

/usr/lib/protonmail/bridge/bridge --cli

Then request login by typing login in the interactive prompt.

Once the sync is completed, a message with Message sync completed will be printed.

vkuznet commented 1 year ago

@LBeernaertProton , this was certainly helpful and I did not realized that sync will take 1.5h. Here is relevant output from the sync procedure:

Sync (vkuznet): 91.4% (Elapsed: 3983.7s, ETA: 377.2s)
ERRO[Mar 21 09:48:01.640] Failed to parse address                       error="no viable alternative at input 'todor <todor>'"
Sync (vkuznet): 91.5% (Elapsed: 3989.5s, ETA: 369.8s)
ERRO[Mar 21 09:48:35.980] Get "https://mail-api.proton.me/mail/v4/messages/UyeoVEwQo6UgWqlySVQqy1-q_NYx4w9Tenbcy55WPjz1Pzb86KEV23H8HrunUfPX4QeEL6FbBAgb98ibPSkEtg==": net/http: timeout awaiting response headers, Attempt 1
ERRO[Mar 21 09:48:35.980] Get "https://mail-api.proton.me/mail/v4/messages/ew4HyNMAX23GxbTjFqubCvrqqt0gPPXE8pXqQJmGup_0hDx5Ws6VKFLznv16u85UbmfGZJOlNQntAxoMVL6wRg==": net/http: timeout awaiting response headers, Attempt 1
ERRO[Mar 21 09:48:37.312] Failed to parse address                       error="no viable alternative at input 'ariza <ariza>'"
Sync (vkuznet): 91.7% (Elapsed: 4028.2s, ETA: 365.3s)
Sync (vkuznet): 91.9% (Elapsed: 4035.4s, ETA: 358.0s)
ERRO[Mar 21 09:48:56.293] Failed to parse address                       error="mismatched input ':' expecting {',', '<', CFWS, QuotedText, EncodedAtom, Atom}"
...
Sync (vkuznet): 100.0% (Elapsed: 4394.3s, ETA: 0.0s)
A sync has finished for vkuznet.

Here, I have few questions:

why sync is required in v3 but not in v2, i.e. when I started v2 with fresh account it worked right away but I didn't verified via cli if sync was done I'm only saying if it was it was very quick
why sync took 1.5 hour?
what sync in fact did? Did it fetched all mail states since I start using account? If so, why is that necessary?
I saw errors during a sync procedure, see above, but I have no idea if they are harmful

But, after the sync I no longer see repeat behavior I reported earlier, so it seems the fresh start with sync helped to resolve the issue. If this is the case, I suggest that you add something to the UI indicating that sync is in progress to give user some indication about ongoing (potentially very long) process. In this regard CLI is very informative but I doubt average user knows about such option.

LBeernaertProton commented 1 year ago

@vkuznet in order of appearance:

The V3 architecture is completely different than the V2 architecture. There was also a Sync step in V2, but here was never any feedback about this step.
Speed of sync depends on the size of your mailbox, connections speed and stability, load of the proton servers and your machine's hardware.
The sync process downloads all message metadata and message contents (body + attachments). This is currently required for V3. V2 also required this, but had an optional mode where the messages did not need to be stored on disk.
From the log output, it seems that have 2 type of errors:
- your connection to proton servers is not stable, hence the network timeouts
- some email addresses are not valid
- both of these are not harmful

Great. Mystery solved :).

In regards to your suggestion, we have already prepared the sync indicator for the GUI internally. We will release this in an update as soon as possible.

vkuznet commented 1 year ago

Thanks for clarification, the issue can be closed now, and remain as reference for other users who may potentially experience similar problem.

vkuznet commented 1 year ago

After using this setup for few days I still see the original problem but not at a scale as before. In other words, for some emails I see them re-appear even if I delete them in my mail client. What have changed is that originally I saw almost every email re-appear (I did not really captured if it was 100% the case or not), but now I see only around 10% of my emails re-appear. It is very difficult to estimate correctly. But I think it is mostly the case when I have a thread and I delete email(s) from such thread. For instance, if I have github issue email, then severals follow-ups and I delete all except final one, then the original (first emails) may reappear. I'll try to keep eye on it and report more precisely.

LBeernaertProton commented 1 year ago

We have a know situation where deleted emails can briefly reappear but they always get removed eventually. Is this also the case for you or do the deleted emails remain there forever?.

vkuznet commented 1 year ago

It seems to be the case, if email reappear I delete it again, and it may appear again. After couple of iteration it is gone. Are you suggesting to not delete it manually and it will be gone by itself?

LBeernaertProton commented 1 year ago

Yes. The message may return briefly before being deleted again. No user interaction is required.

vkuznet commented 1 year ago

Well, I do not see this, if message returns it sits in my mailbox since the pipeline I have is this: goimapsync -> proton bridge -> proton server. You may replace here goimapsync with any other tool which talks to proton bridge and problem will be clear. The proton bridge becomes man-in-a-middle or intermediate IMAP server. My tool/client is configure to talk to proton bridge. Therefore, if I have another device which does not have proton bridge access, e.g. mobile phone, then we may end-up with async behavior between Proton server, and proton bridge, i.e. my mobile client may keep this message around while my laptop client may instruct proton bridge to delete it. I do not know details how in this case all parties will agree on mail state, but it seems to me it is related to proton bridge cache and how often it talks to Proton server. Said that, there is a local cache parameter in proton bridge UI but it only show location of the cache but does not allow to configure its behavior.

I'm still puzzled why version v2.3 have not had such issue though.

LBeernaertProton commented 1 year ago

Multiple clients will re-conciliate these differences and end up with a consistent state.

vkuznet commented 1 year ago

After several days of use I regret to report that it is very serious issue which affects user's productivity. I have repeated messages pop-up randomly in my mail box, and even several times after deletion. I do not observer any pattern, i.e. some messages are back while others are deleted permanently. This is serious issue during peak working hours when I can get literally hundred of emails per day or even in some hour. And, manually keeping track which one I already read and deleted before become unmanageable. I urge you to restore normal functionality as it affects entire usage of email system. I'm glad I saved v2.3.0 and I'm switching back to it to avoid this issue.

LBeernaertProton commented 1 year ago

Did you verify this behavior with a known IMAP client or your custom tool? If the latter, please provide the sequence of IMAP commands your tool is using.

vkuznet commented 1 year ago

@LBeernaertProton , I used goimapsync with Google IMAP before I fully switched to Proton. And, as with v2.3 I never experienced this behavior. Said that, the code relies on go-imap library and main logic I used is in Sync function which does the following:

read new messages from IMAP server (proton bridge in my case)
get local snapshot of maildir on my filesystem
loop over new messages we got from IMAP retrieval and compare them with content of local maildir
if new message is not present in local maildir it will be written over there

I run this workflow as cronjob (and on demand from mutt mail client) in the following form:

gpg -d -o - $HOME/.mutt/goimapsync.gpg | $HOME/bin/goimapsync -op=sync -config - -verbose 0 -profiler=/tmp/goimapsync-profile.log

where my gpg config supports multiple servers, e.g. proton, gmail, imap and smtp, different filters, maildir and local DB. You may get full configuration from config.go and easily construct the configuration file. For me it is very trivial to test proton bridge or any IMAP server in this regard as I can run my workflow on any box (Linux, mac, Windows) and goimapsync is a static executable which does not require any dependency set.

LBeernaertProton commented 1 year ago

@vkuznet please either provide trace logs of the sequence you described or the actual IMAP commands issued by your tool for that given sequence.

Also not that v2 did not have support for the \Recent flag.

vkuznet commented 1 year ago

Hi, sorry for being late, I was busy. I added verbose output to provide IMAP commands sequence, and run it with v2.3.0 version of proton mail bridge when I send to myself a new email with subject Proton-365. Here how it looks like:

egrep "call readImap|365" /tmp/goimapsync.log-365 | grep -v filterMessage
...
2023/04/23 12:50:45 client.go:155: call readImap name=protonmail folder=INBOX read new message true
2023/04/23 12:50:46 client.go:230: read <Imap:protonmail SeqNum:1 HashId:2a99bb5a7713fb2a813064b5f67b8df0 Path: MessageId:<CAKvjti6COSR6pJY5TkfWE8mhj-Sk_9AOUsJSYu4+vBf5AkLWwg@mail.gmail.com> Flags:[nonjunk \Seen] Subject: Proton-365> 1 out of 1 from protonmail
2023/04/23 12:50:46 client.go:706: Read new message <Imap:protonmail SeqNum:1 HashId:2a99bb5a7713fb2a813064b5f67b8df0 Path: MessageId:<CAKvjti6COSR6pJY5TkfWE8mhj-Sk_9AOUsJSYu4+vBf5AkLWwg@mail.gmail.com> Flags:[nonjunk \Seen \Recent] Subject: Proton-365>
2023/04/23 12:50:46 client.go:155: call readImap name=protonmail folder=INBOX read new message false
2023/04/23 12:50:47 client.go:230: read <Imap:protonmail SeqNum:13 HashId:2a99bb5a7713fb2a813064b5f67b8df0 Path: MessageId:<CAKvjti6COSR6pJY5TkfWE8mhj-Sk_9AOUsJSYu4+vBf5AkLWwg@mail.gmail.com> Flags:[\Seen nonjunk] Subject: Proton-365> 13 out of 13 from protonmail

Is it sufficient for your needs? If it is not, please provide more content which should I dump (again I'll need time to figure out if I can do it with my code or will need to modify upstream go-imap library. Here I dump call to my readImap function and flags used in code flow.

alexander-billings commented 1 year ago

I ran into this thread while searching for the issue I was having so I thought I'd offer the solution that worked for me. Just deleting an email did the same behavior, it would go away and then come back and stay in the inbox (I am also seeing where the emails go away, come back, then go away for good but this is different).

When I shift+delete to permanently delete an email or group of emails it stayed deleted. I accidentally solved my problem otherwise I would provide more specifics. I'm going to try changing the "on delete" behavior in Thunderbird and saving some emails that have the issue as it seems only some of the emails have problems.

My email setup: Thunderbird with two email accounts. One Gmail and one Protonmail. Both freshly configured using the vanilla configuration. Only the protonmail account was experiencing the issue.

vkuznet commented 1 year ago

What is a status of this issue now? I still see that deleted emails reappear in my mailbox over and over. I think it is server issue rather the client or communication between ProtonBridge and Proton IMAP server. My client clearly send delete flags to IMAP server but since it goes through ProtonBridge I do not know how ProtonBridge interacts with server and how it propagates Delete flags. In my view it is job of ProtonBridge to ensure that if request to IMAP is requested delete flag for specific mail ID it should not fetch it over regardless of number of independent clients interacting with IMAP server. For instance reappearance of emails I do see in Android ProtonMail app which implies that it is the app misbehavior with IMAP server too. I never saw such behavior with other IMAP servers, e.g. Google mail clients. When I used my soft with Google I never encounter this issue and it gives me confidence that the logic of my client is correct, i.e. it is properly send Delete flags to IMAP server. Therefore, I'm still convince that it is purely ProtonMail bridge or IMAP server issue.

LBeernaertProton commented 1 year ago

We believe this to be related to the the "flickering" issue: E.g.: Mark message as seen and move to trash can briefly cause the message to appear back in its original location before being moved back to Trash.

We are aware of this problem, but it requires to do some "house cleaning" in Bridge first. Work is scheduled to start in the near future.

vkuznet commented 1 year ago

Hi, I would like to know if there is any progress in this. More context. I see that email appearance can happen even after few hours and they can be fetched again many times, i.e. if I delete email now, it can appear immediately after next request to bridge, or it can re-appear in my mailbox after few hours (literally 5 or not hours later), and it can re-appear again after I deleted 2-3 times before. This "feature" is really frustrating and its impact increases with number of emails. On average I delete over and over around 10% of emails from my load, i.e. on average I have 100 emails per day and I need to delete around 10 unique emails on average during a day, but these emails may re-appear again and again. So in overall I need to delete single email 2-3 times if they re-appear.

LBeernaertProton commented 1 year ago

Hey @vkuznet , we are unfortunately, still in the "house cleaning" process.

vkuznet commented 7 months ago

What is the status of this issue, did you get closer to addressing this issue?

ProtonMail / proton-bridge