Ticket #209 (new defect)

Opened 2 years ago

Last modified 1 year ago

POPFile stops working until restart

Reported by: DirkG Assigned to:
Priority: normal Milestone:
Component: unknown Version: 1.1.3
Severity: crash Keywords:
Cc:

Description

Hello,

I am using POPFile for several years now, and the Software is doing an excellent Job.

Unfortunately, since a few days, the Software sometimes stops responding while connecting to an eMail Server, which means that no further mail is being processed and that the website is also unavailable.

After a restart, everything is working again.

What can I do to fix this Problem? - I have already installed the SSL-Fix.

Thanks in advance for your Support!

Best regards Dirk

For your reference, please find attached a short part of my logfile:


2015/10/4 20:00:00 4836: pop3: 546: Attempting to connect to POP server at MAIL-IN.Wobline.De:110 2015/10/4 20:00:00 4836: pop3: 562: Connected to MAIL-IN.Wobline.De:110 timeout 60 2015/10/4 20:00:03 4836: pop3: 682: POP3 proxy done 2015/10/4 20:00:03 4836: pop3: 529: Attempting to connect to SSL server at popmail.t-online.de:995 2015/10/4 20:00:03 4836: pop3: 562: Connected to popmail.t-online.de:995 timeout 60 2015/10/4 20:00:04 4836: pop3: 682: POP3 proxy done 2015/10/4 20:18:02 -13660: bayes: 811: Attempting to connect to dbi:SQLite:dbname=d:\popfile\admini~1/popfile.db (1) 2015/10/4 20:18:02 -13660: bayes: 912: Using SQLite library version 3.7.2 2015/10/4 20:18:03 -13660: smtp: 546: Attempting to connect to POP server at 192.168.0.5:26 2015/10/4 20:18:03 -13660: smtp: 562: Connected to 192.168.0.5:26 timeout 60 2015/10/4 20:18:08 -13660: smtp: 292: SMTP proxy done 2015/10/4 20:18:08 4836: mq: 259: Done with -13660 (0 to go) 2015/10/4 20:19:08 -19540: bayes: 811: Attempting to connect to dbi:SQLite:dbname=d:\popfile\admini~1/popfile.db (1) 2015/10/4 20:19:08 -19540: bayes: 912: Using SQLite library version 3.7.2 2015/10/4 20:19:09 -19540: smtp: 546: Attempting to connect to POP server at 192.168.0.5:26 2015/10/4 20:19:09 -19540: smtp: 562: Connected to 192.168.0.5:26 timeout 60 2015/10/4 20:19:28 -19540: smtp: 292: SMTP proxy done 2015/10/4 20:19:28 4836: mq: 259: Done with -19540 (0 to go) 2015/10/4 20:21:40 -20316: bayes: 811: Attempting to connect to dbi:SQLite:dbname=d:\popfile\admini~1/popfile.db (1) 2015/10/4 20:21:40 -20316: bayes: 912: Using SQLite library version 3.7.2 2015/10/4 20:21:40 -20316: smtp: 546: Attempting to connect to POP server at 192.168.0.5:26 2015/10/4 20:21:40 -20316: smtp: 562: Connected to 192.168.0.5:26 timeout 60 2015/10/4 20:21:42 -20316: smtp: 292: SMTP proxy done 2015/10/4 20:21:42 4836: mq: 259: Done with -20316 (0 to go) 2015/10/4 20:25:59 -19540: bayes: 811: Attempting to connect to dbi:SQLite:dbname=d:\popfile\admini~1/popfile.db (1) 2015/10/4 20:25:59 -19540: bayes: 912: Using SQLite library version 3.7.2 2015/10/4 20:26:00 -19540: smtp: 546: Attempting to connect to POP server at 192.168.0.5:26 2015/10/4 20:26:00 -19540: smtp: 562: Connected to 192.168.0.5:26 timeout 60 2015/10/4 20:26:03 -19540: smtp: 292: SMTP proxy done 2015/10/4 20:26:03 4836: mq: 259: Done with -19540 (0 to go) 2015/10/4 20:30:00 4836: pop3: 546: Attempting to connect to POP server at MAIL-IN.Wobline.De:110 2015/10/4 20:30:00 4836: pop3: 562: Connected to MAIL-IN.Wobline.De:110 timeout 60 2015/10/4 20:30:07 4836: pop3: 682: POP3 proxy done 2015/10/4 20:30:07 4836: pop3: 529: Attempting to connect to SSL server at popmail.t-online.de:995 2015/10/4 20:30:08 4836: pop3: 562: Connected to popmail.t-online.de:995 timeout 60 2015/10/4 20:30:08 4836: pop3: 682: POP3 proxy done 2015/10/4 20:39:24 -12868: bayes: 811: Attempting to connect to dbi:SQLite:dbname=d:\popfile\admini~1/popfile.db (1) 2015/10/4 20:39:24 -12868: bayes: 912: Using SQLite library version 3.7.2 2015/10/4 20:39:26 -12868: smtp: 546: Attempting to connect to POP server at 192.168.0.5:26 2015/10/4 20:39:26 -12868: smtp: 562: Connected to 192.168.0.5:26 timeout 60 2015/10/4 20:39:33 -12868: smtp: 292: SMTP proxy done 2015/10/4 20:39:33 4836: mq: 259: Done with -12868 (0 to go) 2015/10/4 20:49:23 4836: pop3: 546: Attempting to connect to POP server at MAIL-IN.Wobline.De:110 2015/10/4 20:49:23 4836: pop3: 562: Connected to MAIL-IN.Wobline.De:110 timeout 60


After the last line in the logfile, POPFile has stopped working until a restart.

I have already checked the database Status, but without any Errors:


POPFile SQLite Database Status Check (integrated) v0.2.1


Current user : Administrator Current folder: D:\popfile\Administrator Utility folder: D:\popfile Command line : popfile.db

POPFile database found (D:\popfile\Administrator\popfile.db)

SQLite v3.7.2 utility found in D:\popfile

Database is in SQLite 3.x format, uses schema version 3 and its size is 10.247 KB

Result of running the 'pragma integrity_check;' command: ok

The POPFile database has passed the SQLite integrity check!


(report finished 05-Oct-2015 @ 18:25:29)


Moreover, please find the config attached:

bayes_bad_sqlite_version 3.0.0 bayes_corpus corpus bayes_database popfile.db bayes_dbauth bayes_dbconnect dbi:SQLite:dbname=$dbname bayes_dbuser bayes_hostname server01 bayes_localhostname bayes_nihongo_parser kakasi bayes_sqlite_journal_mode delete bayes_sqlite_tweaks 4294967295 bayes_subject_mod_left [ bayes_subject_mod_pos 1 bayes_subject_mod_right ] bayes_unclassified_weight 100 bayes_xpl_angle 0 config_pidcheck_interval 5 config_piddir ./ GLOBAL_debug 1 GLOBAL_last_update_check 1444003200 GLOBAL_message_cutoff 100000 GLOBAL_msgdir messages/ GLOBAL_timeout 60 GLOBAL_update_check 0 history_archive 0 history_archive_classes 0 history_archive_dir archive history_history_days 30 html_cache_templates 0 html_column_characters 0 html_columns +inserted,+from,+to,-cc,+subject,-date,-size,+bucket html_date_format html_language Deutsch html_last_reset Thu Oct 12 22:57:10 2006 html_local 0 html_page_size 200 html_password 307e413b85fe4b36a5320e9f0e29d509 html_port 9090 html_search_filter_highlight 0 html_send_stats 0 html_session_dividers 1 html_show_bucket_help 0 html_show_training_help 0 html_skin simplyblue html_strict_templates 0 html_test_language 0 html_wordtable_format imap_bucket_folder_mappings imap_enabled 0 imap_expunge 0 imap_hostname imap_login imap_password imap_port 143 imap_training_mode 0 imap_uidnexts imap_uidvalidities imap_update_interval 20 imap_use_ssl 0 imap_watched_folders INBOX logger_format default logger_level 0 logger_logdir ./ nntp_enabled 0 nntp_force_fork 0 nntp_headtoo 0 nntp_local 1 nntp_port 119 nntp_separator : nntp_socks_port 1080 nntp_socks_server nntp_welcome_string NNTP POPFile (v0.22.4) server ready pop3_enabled 1 pop3_force_fork 0 pop3_local 0 pop3_port 110 pop3_secure_port 110 pop3_secure_server pop3_separator : pop3_socks_port 1080 pop3_socks_server pop3_toptoo 0 pop3_welcome_string POP3 POPFile (v1.1.3) server ready smtp_chain_port 26 smtp_chain_server 192.168.0.5 smtp_enabled 1 smtp_force_fork 1 smtp_local 0 smtp_port 25 smtp_socks_port 1080 smtp_socks_server smtp_welcome_string SMTP POPFile (v1.1.3) welcome windows_console 0 windows_trayicon 1 xmlrpc_enabled 0 xmlrpc_local 1 xmlrpc_port 8081

Attachments

popfile1443916800.log (31.3 kB) - added by DirkG on 10/05/15 18:36:19.
Logfile
popfile.cfg (2.2 kB) - added by DirkG on 10/05/15 18:36:54.
Config

Change History

10/05/15 18:36:19 changed by DirkG

  • attachment popfile1443916800.log added.

Logfile

10/05/15 18:36:54 changed by DirkG

  • attachment popfile.cfg added.

Config

10/08/15 02:06:46 changed by brian

By default POPFile's log file does not show much detail so many of the entries in your log look like this:

pop3: 529: Attempting to connect to POP server at pop.example.net:110
pop3: 562: Connected to pop.example.net:110 timeout 60
pop3: 682: POP3 proxy done

These entries do not show if any email messages were found and classified.

If you set the logger_level to 1 then the log will show how many new email messages were found on the email server and how many were downloaded. For example if there are no new email messages on the server the log will show something like this:

pop3: 541: Attempting to connect to POP server at pop.example.net:110
pop3: 557: Connected to pop.example.net:110 timeout 60
pop3: 605: Connection returned: +OK connected to pop3 on 3602 [0d][0a]
pop3: 311: USER XXXXXX
pop3: 311: +OK name is a valid mailbox[0d][0a]
pop3: 311: PASS XXXXXX
pop3: 311: +OK user XXXXXX
pop3: 311: STAT[0d][0a]
pop3: 311: +OK 0 0[0d][0a]
pop3: 311: QUIT[0d][0a]
pop3: 311: +OK[0d][0a]
pop3: 682: POP3 proxy done

Some of the troubleshooting pages in the online manual refer to logger_level 2 but this will generate large log files that are not easy to understand. Using logger_level 1 should generate a log file that gives some clues about what POPFile is doing when things go wrong.

The online manual has a page explaining how to change the logger_level and another page showing examples of log file entries.

12/03/15 16:17:55 changed by amatubu

Hi,

POPFile cannot connect multiple POP3 servers at once unless you enable the 'Allow concurrent POP3 connections' option. Also, you cannot access the web interface while POPFile is connecting POP3 servers.

BTW, are you using POP3 proxy and SMTP proxy on a same server?

Naoki

12/03/15 17:40:18 changed by DirkG

Hi Naoki,

I haven't replied with an updated log yet, because Popfile is working again as expected since mid of October. Therefore, no crash and no log with crash information.

At the moment, I have no real idea, why there was the problem in the first place. The only thing I found out that there were a few spam mails in Japanese during the first few crashes, which I haven't seen in the last couple of weeks/ after increasing the log level.

Regarding your last message, I have already used concurrent POP3 connections and POP3 and SMTP Proxies at the same time. Moreover, I am aware, that the Web interface is busy while a POP3 connection exists.

In the last couple of years ( except a few weeks, which let to the ticket) there were no problems at all with concurrent connections and both proxies activated.

Maybe there was a problem with half-open POP3 connections in conjunction with Japanese language messages, which were responsible for the problem. This might also explain, why the problem disappeared from one day to the other without a change in the configuration.

Referring to Japanese language, is there something I can check?

Best regards Dirk