Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG]: Intermittently locked out of fetching #910

Closed
Ghost-Terms opened this issue Mar 18, 2023 · 16 comments
Closed

[BUG]: Intermittently locked out of fetching #910

Ghost-Terms opened this issue Mar 18, 2023 · 16 comments
Assignees
Labels
Component-Core Status-Fixed Ticket is resolved. Type-Defect This is BUG!!!
Milestone

Comments

@Ghost-Terms
Copy link

Ghost-Terms commented Mar 18, 2023

Description of the issue

Seemingly at random, RSS Guard will stop fetching feeds after a while, and the ability to manually fetch feeds or add new feeds will be locked out, as if it thinks it's still fetching feeds in the background.

Symptoms

  1. Options that are disabled during feed fetching will be locked/grayed out, as if fetching is still happening in the background
  2. The button to Stop ongoing fetching will be locked/grayed out, indicating that no feed fetching is currently happening
  3. As expected, the progress bar shown during fetching won't be active

image
image
image

Additional details

I'm using Python (3.11) scripts to convert certain HTML fetched pages to RSS feeds, so that might be related. Maybe RSS Guard's Web Engine is somehow it's getting stuck trying to retrieve a page (Cloudflare-related maybe?), or perhaps there's some sort of issue with the Python script (but if that's the case I'm not sure why the abort option is locked/grayed out).

Debug log

I have a lot of personal feeds and I'd rather not post the full debug log publicly. If there is a place I can email a full debug log, I'll do so.

Here's what I believe is relevant, though:

time=" 14403.808" type="debug" -> core: Filter accepts row 'User (RSS/ATOM/JSON)' and filter result is: 'true'.
time=" 14403.814" type="debug" -> CTRL is NOT pressed while sorting articles - sorting with standard mode.
time=" 14403.816" type="debug" -> message-model: Repopulated model, SQL statement is now:
 'SELECT Messages.id, Messages.is_read, Messages.is_important, Messages.is_deleted, Messages.is_pdeleted, Messages.feed, Messages.title, Messages.url, Messages.author, Messages.date_created, Messages.contents, Messages.enclosures, Messages.score, Messages.account_id, Messages.custom_id, Messages.custom_hash, Feeds.title, CASE WHEN length(Messages.enclosures) > 10 THEN 'true' ELSE 'false' END AS has_enclosures, (SELECT GROUP_CONCAT(Labels.name) FROM Labels WHERE Labels.custom_id IN (SELECT LabelsInMessages.label FROM LabelsInMessages WHERE LabelsInMessages.account_id = Messages.account_id AND LabelsInMessages.message = Messages.custom_id)) as msg_labels FROM Messages LEFT JOIN Feeds ON Messages.feed = Feeds.custom_id AND Messages.account_id = Feeds.account_id WHERE Feeds.custom_id IN ('59') AND Messages.is_deleted = 0 AND Messages.is_pdeleted = 0 AND Messages.account_id = 1 ORDER BY Messages.date_created DESC;'.
time=" 14403.817" type="debug" -> gui: Reloading of msg selections took 3 miliseconds.
time=" 14403.827" type="debug" -> gui: Hovered link: 'QUrl()'.
time=" 14403.828" type="debug" -> core: Silencing GUI message: ''.
time=" 14411.367" type="debug" -> feed-downloader: No feeds to update in worker thread, aborting update.
time=" 14411.367" type="debug" -> core: Notification for event '3' not found
time=" 14411.367" type="debug" -> core: Silencing GUI message: 'I will auto-download new articles for 1 feed.'.
time=" 14421.092" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14431.091" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14441.090" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14451.087" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14461.088" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14471.086" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14481.087" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14491.087" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14501.092" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14511.090" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14521.082" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14531.094" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time=" 14541.088" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.

(It will continue to do the 'Delaying scheduled feed' line until I restart the program.)

Operating system and version

  • OS: Windows 10 22H2
  • RSS Guard version: 4.3.2 rev 085d5be
@Ghost-Terms
Copy link
Author

Ghost-Terms commented Mar 20, 2023

This hasn't happened in the past 24 hours (even though I haven't changed anything), whereas before it was happening at least once every three hours. I think it has to be related to the retrieval via WebEngine getting stuck on something, rather than anything to do with the Python scripts.

@martinrotter
Copy link
Owner

This hasn't happened in the past 24 hours (even though I haven't changed anything), whereas before it was happening at least once every three hours. I think it has to be related to the retrieval via WebEngine getting stuck on something, rather than anything to do with the Python scripts.

I see. Do you use anything "special" in your setup? Article filters, web scraping or?

@Ghost-Terms
Copy link
Author

This hasn't happened in the past 24 hours (even though I haven't changed anything), whereas before it was happening at least once every three hours. I think it has to be related to the retrieval via WebEngine getting stuck on something, rather than anything to do with the Python scripts.

I see. Do you use anything "special" in your setup? Article filters, web scraping or?

Most of my feeds are. I tend to use Feedbro in my browser for normal RSS feeds and RSS Guard for my own custom feeds using Python. However, I only use them as post-processors rather than having the Python script download the page.

I was initially thinking it might be a Python script problem, but considering this issue was happening to me frequently and then suddenly just stopped makes me think that it's something to with the page retrieval.

@Ghost-Terms
Copy link
Author

It started happening again today, and it's been happening practically all day. Zero changes to my settings.

@martinrotter
Copy link
Owner

martinrotter commented Apr 4, 2023

I see. I was not able to replicate so far. Could you perhaps create some minimal setup (data4 folder) and share the folder with me including scripts you use etc.?

EDIT: I suspect this is related rather to fact you use post-scripts rather than the amount of feeds...

@Ghost-Terms
Copy link
Author

I see. I was not able to replicate so far. Could you perhaps create some minimal setup (data4 folder) and share the folder with me including scripts you use etc.?

EDIT: I suspect this is related rather to fact you use post-scripts rather than the amount of feeds...

Would it be possible to email you with the setup?

@martinrotter
Copy link
Owner

Yes: rotter.martinos(at)gmail.com

@Ghost-Terms
Copy link
Author

Ghost-Terms commented Apr 7, 2023

Please excuse me for the radio silence, but I've been narrowing down what's been causing this issue. I don't think it's actually a problem with fetching at all.

  1. I made a duplicate of my RSS Guard installation and found there was one folder where, if I got rid of it, auto-fetching would happen in the background normally again.

  2. I then made a new duplicate installation and instead of removing the folder, I instead disabled every feed inside of it. Interestingly, this did not fix the issue and auto-fetching was broken.

  3. To make sure it wasn't a fluke, I then deleted the folder and auto-fetching began working normally again.

This means it would be very difficult to replicate with a new setup. However, I have managed to generate a rather short debug log where the issue occurs:

Debug Log


Line 237 is the suspected culprit, which reads:

time=" 610.733" type="debug" -> core: Notification for event '3' not found

Downloadable copy of the following:

time="     0.242" type="debug" -> core: Initializing settings in 'D:\RSS Guard\data4\config\config.ini' (portable way).
time="     0.254" type="info" -> 

GL Type: desktop
Surface Type: OpenGL
Surface Profile: CompatibilityProfile
Surface Version: 4.6
QSG RHI Backend: OpenGL
Using Supported QSG Backend: yes
Using Software Dynamic GL: no
Using Multithreaded OpenGL: yes

Init Parameters:
  *  application-name rssguard 
  *  browser-subprocess-path D:\RSS Guard\QtWebEngineProcess.exe 
  *  create-default-gl-context  
  *  disable-es3-gl-context  
  *  disable-features ConsolidatedMovementXY,InstalledApp,BackgroundFetch,WebOTP,WebPayments,WebUSB,PictureInPicture 
  *  disable-speech-api  
  *  enable-features NetworkServiceInProcess,TracingServiceInProcess 
  *  enable-smooth-scrolling  
  *  enable-threaded-compositing  
  *  in-process-gpu  
  *  use-gl desktop 

time="     0.701" type="debug" -> database: File-based SQLite database connection 'DatabaseFactory' to file 'D:\RSS Guard\data4\database\database.db' seems to be established.
time="     0.702" type="debug" -> database: File-based SQLite database has version '4'.
time="     0.703" type="debug" -> gui: Available icon theme paths: QList(:/icons, :/graphics, D:\RSS Guard\data4\icons, D:/RSS Guard/icons)
time="     0.704" type="debug" -> gui: Installed icon themes are: '', 'Breeze', 'Breeze Dark', 'Faenza', 'Numix'
time="     0.704" type="debug" -> gui: Loading icon theme 'Breeze Dark'.
time="     0.705" type="debug" -> gui: Found path of base skin: ':\skins\nudus-base'.
time="     0.705" type="debug" -> gui: Local file ':\skins\nudus-dark\html_wrapper.html' exists, using it for the skin.
time="     0.705" type="debug" -> gui: Local file ':\skins\nudus-dark\html_style.css' exists, using it for the skin.
time="     0.705" type="debug" -> gui: Trying to load base file ':\skins\nudus-base\html_enclosure_image.html' for the skin.
time="     0.706" type="debug" -> gui: Trying to load base file ':\skins\nudus-base\html_single_message.html' for the skin.
time="     0.706" type="debug" -> gui: Trying to load base file ':\skins\nudus-base\html_enclosure_every.html' for the skin.
time="     0.706" type="debug" -> gui: Local file ':\skins\nudus-dark\qt_style.qss' exists, using it for the skin.
time="     0.706" type="debug" -> gui: Trying to load base file ':\skins\nudus-base\html_adblocked.html' for the skin.
time="     0.707" type="debug" -> gui: Setting style: 'Fusion'.
time="     0.707" type="debug" -> gui: Activating alternative palette.
time="     0.707" type="debug" -> gui: Skin 'nudus-dark' loaded.
time="     0.708" type="debug" -> network: Persistent web data storage path: 'D:\RSS Guard\data4\web\storage'.
time="     0.708" type="debug" -> network: Disabling application-wide proxy completely.
time="     0.715" type="debug" -> core: OpenSSL version: 'OpenSSL 1.1.1q  5 Jul 2022'.
time="     0.715" type="debug" -> core: OpenSSL supported: 'true'.
time="     0.715" type="debug" -> core: Global thread pool has 8 threads.
time="     0.715" type="debug" -> core: Starting RSS Guard 4.3.2.
time="     0.715" type="debug" -> core: Instantiated class  'Application'.
time="     0.716" type="debug" -> core: Starting to load active localization. Desired localization is 'en_US'.
time="     0.717" type="debug" -> core: Application localization 'en_US' loaded successfully, specifically sublocalization 'en_US' was loaded.
time="     0.717" type="warning" -> core: Qt localization 'en_US' WAS NOT loaded successfully.
time="     0.721" type="debug" -> database: SQLite database connection 'MessagesModel' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.723" type="debug" -> message-model: Repopulated model, SQL statement is now:
 'SELECT Messages.id, Messages.is_read, Messages.is_important, Messages.is_deleted, Messages.is_pdeleted, Messages.feed, Messages.title, Messages.url, Messages.author, Messages.date_created, Messages.contents, Messages.enclosures, Messages.score, Messages.account_id, Messages.custom_id, Messages.custom_hash, Feeds.title, CASE WHEN length(Messages.enclosures) > 10 THEN 'true' ELSE 'false' END AS has_enclosures, (SELECT GROUP_CONCAT(Labels.name) FROM Labels WHERE Labels.custom_id IN (SELECT LabelsInMessages.label FROM LabelsInMessages WHERE LabelsInMessages.account_id = Messages.account_id AND LabelsInMessages.message = Messages.custom_id)) as msg_labels FROM Messages LEFT JOIN Feeds ON Messages.feed = Feeds.custom_id AND Messages.account_id = Feeds.account_id WHERE 0 > 1;'.
time="     0.724" type="debug" -> core: Auto-download timer started with interval 10000 ms.
time="     0.724" type="debug" -> core: Creating FeedDownloader singleton.
time="     0.728" type="debug" -> gui: Creating main application form in thread: '0x4280'.
time="     0.738" type="debug" -> gui: Current row changed - proxy 'QModelIndex(-1,-1,0x0,QObject(0x0))', source 'QModelIndex(-1,-1,0x0,QObject(0x0))'.
time="     0.754" type="debug" -> network: Settings of BaseNetworkAccessManager loaded.
time="     0.827" type="debug" -> gui: Creating tray icon menu.
time="     0.862" type="debug" -> CTRL is NOT pressed while sorting articles - sorting with standard mode.
time="     0.863" type="debug" -> message-model: Repopulated model, SQL statement is now:
 'SELECT Messages.id, Messages.is_read, Messages.is_important, Messages.is_deleted, Messages.is_pdeleted, Messages.feed, Messages.title, Messages.url, Messages.author, Messages.date_created, Messages.contents, Messages.enclosures, Messages.score, Messages.account_id, Messages.custom_id, Messages.custom_hash, Feeds.title, CASE WHEN length(Messages.enclosures) > 10 THEN 'true' ELSE 'false' END AS has_enclosures, (SELECT GROUP_CONCAT(Labels.name) FROM Labels WHERE Labels.custom_id IN (SELECT LabelsInMessages.label FROM LabelsInMessages WHERE LabelsInMessages.account_id = Messages.account_id AND LabelsInMessages.message = Messages.custom_id)) as msg_labels FROM Messages LEFT JOIN Feeds ON Messages.feed = Feeds.custom_id AND Messages.account_id = Feeds.account_id WHERE 0 > 1 ORDER BY Messages.date_created DESC;'.
time="     0.871" type="debug" -> core: Hiding the main window when the application is starting.
time="     0.871" type="debug" -> database: SQLite database connection 'FeedReader' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.872" type="debug" -> database: SQLite database connection 'FeedlyEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.873" type="debug" -> database: SQLite database connection 'GmailEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.874" type="debug" -> database: SQLite database connection 'GreaderEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.874" type="debug" -> database: SQLite database connection 'OwnCloudServiceEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.875" type="debug" -> database: SQLite database connection 'StandardServiceEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.879" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     0.880" type="debug" -> database: SQLite database connection 'StandardServiceRoot' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.881" type="debug" -> core: Custom ID of feed when loading from DB is '8'.
time="     0.882" type="debug" -> core: Custom ID of feed when loading from DB is '9'.
time="     0.882" type="debug" -> core: Custom ID of feed when loading from DB is '10'.
time="     0.883" type="debug" -> core: Custom ID of feed when loading from DB is '11'.
time="     0.883" type="debug" -> core: Custom ID of feed when loading from DB is '12'.
time="     0.884" type="debug" -> core: Custom ID of feed when loading from DB is '13'.
time="     0.885" type="debug" -> core: Custom ID of feed when loading from DB is '14'.
time="     0.886" type="debug" -> core: Custom ID of feed when loading from DB is '17'.
time="     0.886" type="debug" -> core: Custom ID of feed when loading from DB is '18'.
time="     0.886" type="debug" -> core: Custom ID of feed when loading from DB is '20'.
time="     0.888" type="debug" -> core: Custom ID of feed when loading from DB is '21'.
time="     0.889" type="debug" -> core: Custom ID of feed when loading from DB is '28'.
time="     0.898" type="debug" -> core: Custom ID of feed when loading from DB is '31'.
time="     0.902" type="debug" -> core: Custom ID of feed when loading from DB is '32'.
time="     0.903" type="debug" -> core: Custom ID of feed when loading from DB is '38'.
time="     0.905" type="debug" -> core: Custom ID of feed when loading from DB is '39'.
time="     0.906" type="debug" -> core: Custom ID of feed when loading from DB is '40'.
time="     0.907" type="debug" -> core: Custom ID of feed when loading from DB is '41'.
time="     0.908" type="debug" -> core: Custom ID of feed when loading from DB is '44'.
time="     0.908" type="debug" -> core: Custom ID of feed when loading from DB is '45'.
time="     0.909" type="debug" -> core: Custom ID of feed when loading from DB is '48'.
time="     0.909" type="debug" -> core: Custom ID of feed when loading from DB is '49'.
time="     0.910" type="debug" -> core: Custom ID of feed when loading from DB is '50'.
time="     0.910" type="debug" -> core: Custom ID of feed when loading from DB is '51'.
time="     0.911" type="debug" -> core: Custom ID of feed when loading from DB is '52'.
time="     0.911" type="debug" -> core: Custom ID of feed when loading from DB is '53'.
time="     0.912" type="debug" -> core: Custom ID of feed when loading from DB is '54'.
time="     0.913" type="debug" -> core: Custom ID of feed when loading from DB is '56'.
time="     0.915" type="debug" -> core: Custom ID of feed when loading from DB is '57'.
time="     0.916" type="debug" -> core: Custom ID of feed when loading from DB is '58'.
time="     0.916" type="debug" -> core: Custom ID of feed when loading from DB is '59'.
time="     0.917" type="debug" -> core: Custom ID of feed when loading from DB is '60'.
time="     0.918" type="debug" -> core: Custom ID of feed when loading from DB is '61'.
time="     0.919" type="debug" -> core: Custom ID of feed when loading from DB is '62'.
time="     0.920" type="debug" -> core: Custom ID of feed when loading from DB is '63'.
time="     0.920" type="debug" -> core: Custom ID of feed when loading from DB is '64'.
time="     0.921" type="debug" -> core: Custom ID of feed when loading from DB is '65'.
time="     0.922" type="debug" -> core: Custom ID of feed when loading from DB is '66'.
time="     0.922" type="debug" -> core: Custom ID of feed when loading from DB is '67'.
time="     0.923" type="debug" -> core: Custom ID of feed when loading from DB is '68'.
time="     0.924" type="debug" -> core: Custom ID of feed when loading from DB is '69'.
time="     0.924" type="debug" -> database: SQLite database connection 'RecycleBin' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.935" type="debug" -> database: SQLite database connection 'ImportantNode' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.937" type="debug" -> database: SQLite database connection 'RootItem' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.938" type="debug" -> database: SQLite connection 'StandardServiceRoot' is already active.
time="     0.938" type="debug" -> database: SQLite database connection 'StandardServiceRoot' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.941" type="debug" -> database: SQLite database connection 'TtRssServiceEntryPoint' to file 'D:/RSS Guard/data4/database/database.db' seems to be established.
time="     0.942" type="debug" -> gui: User wants to have tray icon.
time="     0.942" type="debug" -> gui: Tray icon is available, showing now.
time="     0.945" type="debug" -> gui: Creating SystemTrayIcon instance.
time="     0.965" type="debug" -> gui: Showing tray icon immediately.
time="     1.212" type="debug" -> gui: Tray icon displayed.
time="     1.212" type="debug" -> gui: Feed list item expanded - User (RSS/ATOM/JSON)
time="     1.213" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.213" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.213" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.213" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.214" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.214" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.214" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.214" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.214" type="debug" -> gui: Feed list item expanded - ##########
time="     1.215" type="debug" -> gui: Feed list item expanded - ##########
time="     1.215" type="debug" -> gui: Feed list item expanded - ##########
time="     1.215" type="debug" -> gui: Feed list item expanded - ##########
time="     1.221" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.221" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.222" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.222" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.223" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.223" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.224" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.224" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.225" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.225" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.226" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.226" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.226" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.227" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.227" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.227" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.227" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.227" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.228" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.228" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.228" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.229" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.229" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.229" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.229" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.230" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.230" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.230" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.230" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.231" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.231" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.231" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.231" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.232" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.232" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.232" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.233" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.233" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.233" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.233" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.239" type="debug" -> core: No execution message received from other app instances.
time="     1.276" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.276" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.277" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.277" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.277" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.277" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.277" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.279" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.280" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.281" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.281" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.282" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.282" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.282" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.283" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.287" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.287" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.288" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.288" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.288" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.288" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.290" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.291" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.291" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.292" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.292" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.292" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.293" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.293" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.293" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.293" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.293" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.294" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.294" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.294" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.294" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.295" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.295" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.296" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.296" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.296" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.296" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.297" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.297" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.302" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.303" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.304" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.304" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.305" type="debug" -> core: Filter accepts row '########' and filter result is: 'true'.
time="     1.438" type="debug" -> gui: Hovered link: 'QUrl()'.
time="     1.438" type="debug" -> core: Silencing GUI message: ''.
time="    46.443" type="debug" -> core: Saved data with auto-saver for 'CookieJar' and method 'saveCookies'.
time="    88.961" type="debug" -> gui: Message splitter moved.
time="    90.723" type="debug" -> core: Delaying scheduled feed auto-download for some time since window is focused and updates while focused are disabled by the user and all account caches are empty.
time="    94.337" type="debug" -> gui: Main window's close event
time="    94.394" type="debug" -> gui: Main window's hide event
time="   598.521" type="debug" -> gui: Main window's close event
time="   598.525" type="debug" -> gui: Main window's hide event
time="   610.733" type="debug" -> core: Notification for event '3' not found
time="   610.734" type="debug" -> feed-downloader: No feeds to update in worker thread, aborting update.
time="   610.734" type="debug" -> core: Silencing GUI message: 'I will auto-download new articles for 1 feed.'.
time="   620.725" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   630.725" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   640.733" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   650.728" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   660.736" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   670.734" type="debug" -> core: Delaying scheduled feed auto-download for some time since window is focused and updates while focused are disabled by the user and all account caches are empty.
time="   673.360" type="debug" -> gui: Main window's hide event
time="   680.724" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   690.734" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   700.723" type="debug" -> core: Delaying scheduled feed auto-downloads and message state synchronization for one minute due to another running update.
time="   706.504" type="debug" -> gui: Main window's close event
time="   706.511" type="debug" -> gui: Main window's hide event
time="   708.532" type="debug" -> core: Cleaning up resources and saving application state.
time="   708.533" type="warning" -> core: Close lock timed-out.
time="   708.533" type="debug" -> core: Stopping StandardServiceRoot instance.
time="   708.533" type="debug" -> feed-downloader: Destroying FeedDownloader instance.
time="   708.549" type="debug" -> gui: Destroying FormMain instance.
time="   708.550" type="debug" -> gui: Destroying TabWidget instance.
time="   708.550" type="debug" -> gui: Destroying FeedMessageViewer instance.
time="   708.550" type="debug" -> gui: Destroying BaseToolBar instance.
time="   708.554" type="debug" -> network: Destroying Downloader instance.
time="   708.555" type="debug" -> network: Destroying SilentNetworkAccessManager instance.
time="   708.570" type="debug" -> gui: Destroying MessagesView instance.
time="   708.573" type="debug" -> gui: Destroying BaseToolBar instance.
time="   708.576" type="debug" -> gui: Destroying FeedsView instance.
time="   708.579" type="debug" -> gui: Destroying TabBar instance.
time="   708.583" type="debug" -> gui: Destroying StatusBar instance.
time="   708.585" type="debug" -> gui: Destroying SystemTrayIcon instance.
time="   708.829" type="debug" -> core: Destroying Application instance.
time="   708.829" type="debug" -> core: Destroying Mutex instance.
time="   708.830" type="warning" -> QMutex: destroying locked mutex
time="   708.873" type="debug" -> gui: Destroying IconFactory instance.
time="   708.873" type="debug" -> core: Destroying FeedReader instance.
time="   708.873" type="debug" -> feed-model: Destroying FeedsModel instance.
time="   708.874" type="debug" -> feed-model: Destroying FeedsProxyModel instance
time="   708.874" type="debug" -> message-model: Destroying MessagesModel instance.
time="   708.876" type="debug" -> message-model: Destroying MessagesProxyModel instance.

If this isn't enough, I can continue chopping away at this so I can have something to send you that replicates the issue right away. However, I suspect that just making sure an event not being found doesn't cause feed auto-downloads to be blocked will do the trick.

@BoboGargle
Copy link

I've just installed a day or so ago, same issue. Does not update, cannot manually update. Only solution is a restart.,

@martinrotter
Copy link
Owner

Can you share your data folder?

@Ghost-Terms
Copy link
Author

Ghost-Terms commented Apr 9, 2023

I think I finally know what's causing it. It's when you set a single feed's auto-download duration in the Articles tab instead of having it use the global interval.

The reason I failed to detect it for so long is it will even cause the bug if the feed is disabled.

@BoboGargle
Copy link

Setting the feeds to the global interval appears to have resolved the problem for me too.

@martinrotter
Copy link
Owner

Could anyone post config which triggers the issue?

@Ghost-Terms
Copy link
Author

Could anyone post config which triggers the issue?

I emailed you a config that replicates the issue yesterday.

martinrotter added a commit that referenced this issue Apr 12, 2023
@martinrotter
Copy link
Owner

OK, guys, it was beginner noobish classic programming fault. It should be fixed. Test and see and report back.

@martinrotter martinrotter added this to the 4.3.4 milestone Apr 12, 2023
@Ghost-Terms
Copy link
Author

I'm glad to prove the innocence of my post-processing scripts. ;)

Thanks for the fix, it's working for me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Component-Core Status-Fixed Ticket is resolved. Type-Defect This is BUG!!!
Projects
None yet
Development

No branches or pull requests

3 participants