naoki iimura - 2007-12-14

A user reported that POPFile sometimes crashed by simultaneous POP3 and
UI accesses on Windows. He is using POPFile 0.22.5 on Windows 2000 Pro
with 'Allow concurrent POP3 connections' option.

I tried to reproduce the problem, and I found the way to crash POPFile.
If a POP3 connection is closed while POPFile is processing to display
the 'Single Message View' on the UI, POPFile will crash.

Here's the Dr Watson's crash log (in Japanese):
http://idisk.mac.com/amatubu/Public/POPFile/drwatson_log.txt

POPFile's log:

2007/12/13 13:15:04 -2464: bayes: 747: Attempting to connect to dbi:SQLite2:dbname=C:\DOCUME~1\user\APPLIC~1\POPFile/popfile.db (1)
2007/12/13 13:15:04 -2464: bayes: 753: Using SQLite library version 2.8.15
2007/12/13 13:15:04 -2464: pop3: 301: +OK POP3 POPFile (v1.0.0) server ready[0d][0a]
2007/12/13 13:15:04 -2464: pop3: 194: Regexps: ^USER XXXXXX
2007/12/13 13:15:04 -2464: pop3: 209: Command: --user XXXXXX--
2007/12/13 13:15:04 -2464: mq: 377: post LOGIN (user)
2007/12/13 13:15:04 -2464: mq: 392: sending post LOGIN (user) to parent GLOB(0x349b894)
2007/12/13 13:15:04 4052: mq: 377: post LOGIN (user)
2007/12/13 13:15:04 4052: mq: 384: queuing post LOGIN (user)
2007/12/13 13:15:04 4052: mq: 386: LOGIN queue length now 0
2007/12/13 13:15:04 4052: mq: 128: Message LOGIN (user) ready for delivery
2007/12/13 13:15:04 4052: mq: 131: Delivering message LOGIN (user) to html
2007/12/13 13:15:07 4052: html: 658: Read slurp data GET /view?view=760&start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/vnd.ms-exc
2007/12/13 13:15:07 4052: html: 154: GET /view?view=760&start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]
2007/12/13 13:15:07 4052: html: 658: Read slurp data el, application/vnd.ms-powerpoint, application/msword, application/x-shockwave-flash, */*[0d][0a]Referer: http://127.0.0.1:8080/history?start_message=0&session=55hwBy
2007/12/13 13:15:07 4052: html: 658: Read slurp data n6&sort=-inserted[0d][0a]Accept-Language: ja[0d][0a]Accept-Encoding: gzip, deflate[0d][0a]User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1) Sleipnir/2.6.0[0d][0a]Host
2007/12/13 13:15:07 4052: html: 658: Read slurp data : 127.0.0.1:8080[0d][0a]Connection: Keep-Alive[0d][0a][0d][0a]
2007/12/13 13:15:15 4052: html: 181: HTTP handle_url returned code 1[0a]
2007/12/13 13:15:15 4052: html: 189: Close HTTP connection on IO::Socket::INET=GLOB(0x306d9cc)[0a]
2007/12/13 13:15:18 4052: html: 658: Read slurp data GET /history?start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/vnd.ms-excel, ap
2007/12/13 13:15:18 4052: html: 154: GET /history?start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]
2007/12/13 13:15:18 4052: html: 658: Read slurp data plication/vnd.ms-powerpoint, application/msword, application/x-shockwave-flash, */*[0d][0a]Referer: http://127.0.0.1:8080/view?view=760&start_message=0&session=55hwBy
2007/12/13 13:15:18 4052: html: 658: Read slurp data n6&sort=-inserted[0d][0a]Accept-Language: ja[0d][0a]Accept-Encoding: gzip, deflate[0d][0a]User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1) Sleipnir/2.6.0[0d][0a]Host
2007/12/13 13:15:18 4052: html: 658: Read slurp data : 127.0.0.1:8080[0d][0a]Connection: Keep-Alive[0d][0a][0d][0a]
2007/12/13 13:15:18 4052: history: 1100: Request for rows 1 (20), current size 21
2007/12/13 13:15:18 4052: history: 1112: Returning 0..19
2007/12/13 13:15:20 4052: html: 181: HTTP handle_url returned code 1[0a]
2007/12/13 13:15:21 4052: html: 189: Close HTTP connection on IO::Socket::INET=GLOB(0x3083bc4)[0a]
2007/12/13 13:15:24 4052: html: 658: Read slurp data GET /view?view=749&start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/vnd.ms-exc
2007/12/13 13:15:24 4052: html: 154: GET /view?view=749&start_message=0&session=55hwByn6&sort=-inserted HTTP/1.1[0d][0a]
2007/12/13 13:15:24 4052: html: 658: Read slurp data el, application/vnd.ms-powerpoint, application/msword, application/x-shockwave-flash, */*[0d][0a]Referer: http://127.0.0.1:8080/history?start_message=0&session=55hwBy
2007/12/13 13:15:24 4052: html: 658: Read slurp data n6&sort=-inserted[0d][0a]Accept-Language: ja[0d][0a]Accept-Encoding: gzip, deflate[0d][0a]User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1) Sleipnir/2.6.0[0d][0a]Host
2007/12/13 13:15:24 4052: html: 658: Read slurp data : 127.0.0.1:8080[0d][0a]Connection: Keep-Alive[0d][0a][0d][0a]
2007/12/13 13:15:25 -2464: pop3: 512: Attempting to connect to POP server at pop.example.jp:110
2007/12/13 13:15:25 -2464: pop3: 301: -ERR can't connect to pop.example.jp:110[0d][0a]
2007/12/13 13:15:25 -2464: pop3: 209: Command: --quit--
2007/12/13 13:15:25 -2464: pop3: 301: +OK goodbye[0d][0a]
2007/12/13 13:15:25 -2464: mq: 377: post CMPLT (-2464)
2007/12/13 13:15:25 -2464: mq: 392: sending post CMPLT (-2464) to parent GLOB(0x349b894)
2007/12/13 13:15:25 -2464: pop3: 668: POP3 proxy done

A perl script to reproduce the problem:
http://idisk.mac.com/amatubu/Public/POPFile/concurrent_test.pl

This script will access POPFile's POP3 proxy and UI simultaneously.
It requires LWP (libwwwperl) module. And please change the variables
for your configuration.

Execute this script several times, and POPFile will die.
If you choose a large message to download, you can see the crash easily.

I think this is a serious problem, but I don't know how to solve it.
I'm thinking whether closing thread (pseudo process) affects POPFile.

I've post a bug report #1850672:
https://sourceforge.net/tracker/index.php?func=detail&aid=1850672&group_id=63137&atid=502956

Naoki