E-Mail dependency hangs 24x7

In regards to processing .TXT attachments it may be affected by email message composition and encoding. 24x7 expects multi-part messages using MIME encoding. It breaks each message into multiple parts and saves each part using file name specified in the part properties. Please check if the sender is using MIME encoding when sending email messages.

Did it get hung while scanning email or at some other moment? Any clues in the debug.log trace file (with tracing option enabled)

Here's the details on a couple of hangs, maybe they'll help.

24x7 eventually recovered from the first hang after 5 mins. On the second one it still hadn't come back after 15 so I killed it. During the hang javaw.exe takes 30-80% of the CPU. The test job polls every minute. Nothing has been saved into the temp directory.

debug log from first hang at 1144. 24x7 was running happily for 20 minutes with no messages in the POP mailbox, it was only after I sent a message that it hung:

Quote:

2008-03-17 11:34:24,109 [Thread-11958] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:35:27,453 [Thread-12128] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:36:24,062 [Thread-12298] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:37:24,109 [Thread-12468] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:38:24,109 [Thread-12638] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:39:24,078 [Thread-12808] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 0
2008-03-17 11:40:24,093 [Thread-12978] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 1
2008-03-17 11:42:37,500 [Thread-15307] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 1
2008-03-17 11:44:05,703 [Thread-90330] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 1
2008-03-17 11:48:03,953 [Thread-143526] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 1
2008-03-17 11:49:27,343 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.JobDbImpl - updateJob(JobProperties) : start
2008-03-17 11:49:27,359 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - update(...) : start
2008-03-17 11:49:27,359 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - update(...) : end
2008-03-17 11:49:27,359 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.JobDbImpl - updateJob(JobProperties) : end

POP trace of same:

Quote:

16467 11:39:23.815214 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop6)
16468 11:39:23.891124 192.168.1.36 203.97.33.231 POP Request: USER tomrob
16470 11:39:23.847737 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
16471 11:39:23.923608 192.168.1.36 203.97.33.231 POP Request: PASS ***
16477 11:39:24.058945 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
16478 11:39:24.134851 192.168.1.36 203.97.33.231 POP Request: STAT
16479 11:39:24.106330 203.97.33.231 192.168.1.36 POP Response: +OK 0 0
16480 11:39:24.182309 192.168.1.36 203.97.33.231 POP Request: QUIT
16481 11:39:24.138801 203.97.33.231 192.168.1.36 POP Response: +OK
16489 11:39:24.210610 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop4)
16490 11:39:24.286552 192.168.1.36 203.97.33.231 POP Request: USER tomrob
16492 11:39:24.227017 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
16493 11:39:24.302888 192.168.1.36 203.97.33.231 POP Request: PASS ***
16510 11:39:24.438227 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
16511 11:39:24.514171 192.168.1.36 203.97.33.231 POP Request: QUIT
16512 11:39:24.488809 203.97.33.231 192.168.1.36 POP Response: +OK
17069 11:40:23.811816 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop5)
17070 11:40:23.887695 192.168.1.36 203.97.33.231 POP Request: USER tomrob
17072 11:40:23.843652 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
17073 11:40:23.919495 192.168.1.36 203.97.33.231 POP Request: PASS ***
17077 11:40:24.039801 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
17078 11:40:24.115671 192.168.1.36 203.97.33.231 POP Request: STAT
17079 11:40:24.089559 203.97.33.231 192.168.1.36 POP Response: +OK 1 2398
17080 11:40:24.119736 192.168.1.36 203.97.33.231 POP Request: UIDL
17081 11:40:24.153185 203.97.33.231 192.168.1.36 POP Response: +OK unique-id listing follows
17082 11:40:24.229554 192.168.1.36 203.97.33.231 POP Request: TOP 1 0
17084 11:40:24.191828 203.97.33.231 192.168.1.36 POP [TCP Previous segment lost] Continuation
17086 11:40:24.193268 203.97.33.231 192.168.1.36 POP [TCP Out-Of-Order] Response: +OK
17088 11:40:24.314391 192.168.1.36 203.97.33.231 POP Request: RETR 1
17089 11:40:24.285273 203.97.33.231 192.168.1.36 POP Response: +OK 2398 octets
17090 11:40:24.286067 203.97.33.231 192.168.1.36 POP Continuation
17092 11:40:24.368805 192.168.1.36 203.97.33.231 POP Request: QUIT
17093 11:40:24.331588 203.97.33.231 192.168.1.36 POP Response: +OK
17101 11:40:24.414515 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop4)
17102 11:40:24.490367 192.168.1.36 203.97.33.231 POP Request: USER tomrob
17104 11:40:24.447828 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
17105 11:40:24.523678 192.168.1.36 203.97.33.231 POP Request: PASS ***
17107 11:40:24.715969 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
17108 11:40:24.791821 192.168.1.36 203.97.33.231 POP Request: QUIT
17110 11:40:24.760518 203.97.33.231 192.168.1.36 POP Response: +OK
18463 11:42:37.303062 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop4)
18464 11:42:37.229941 192.168.1.36 203.97.33.231 POP Request: USER tomrob
18466 11:42:37.260340 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
18467 11:42:37.260441 192.168.1.36 203.97.33.231 POP Request: PASS ***
18478 11:42:37.468572 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
18479 11:42:37.468701 192.168.1.36 203.97.33.231 POP Request: STAT
18480 11:42:37.519044 203.97.33.231 192.168.1.36 POP Response: +OK 1 2398
18481 11:42:37.519218 192.168.1.36 203.97.33.231 POP Request: UIDL
18488 11:42:37.552066 203.97.33.231 192.168.1.36 POP Response: +OK unique-id listing follows
18489 11:42:37.552194 192.168.1.36 203.97.33.231 POP Request: TOP 1 0
18492 11:42:37.583977 203.97.33.231 192.168.1.36 POP [TCP Previous segment lost] Continuation
18494 11:42:37.585429 203.97.33.231 192.168.1.36 POP [TCP Out-Of-Order] Response: +OK
18496 11:42:37.663064 192.168.1.36 203.97.33.231 POP Request: RETR 1
18497 11:42:37.618342 203.97.33.231 192.168.1.36 POP Response: +OK 2398 octets
18498 11:42:37.619133 203.97.33.231 192.168.1.36 POP Continuation
18500 11:42:37.619808 192.168.1.36 203.97.33.231 POP Request: QUIT
18501 11:42:37.652177 203.97.33.231 192.168.1.36 POP Response: +OK
18509 11:42:37.741054 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop6)
18510 11:42:37.741105 192.168.1.36 203.97.33.231 POP Request: USER tomrob
18514 11:42:37.775652 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
18515 11:42:37.775733 192.168.1.36 203.97.33.231 POP Request: PASS ***
18517 11:42:37.994304 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
18518 11:42:38.070163 192.168.1.36 203.97.33.231 POP Request: QUIT
18520 11:42:38.042932 203.97.33.231 192.168.1.36 POP Response: +OK
19163 11:44:04.883921 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop4)
19182 11:44:05.519169 192.168.1.36 203.97.33.231 POP Request: USER tomrob
19186 11:44:05.472701 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
19187 11:44:05.548538 192.168.1.36 203.97.33.231 POP Request: PASS ***
19193 11:44:05.759900 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
19194 11:44:05.684309 192.168.1.36 203.97.33.231 POP Request: STAT
19195 11:44:05.732087 203.97.33.231 192.168.1.36 POP Response: +OK 1 2398
19196 11:44:05.810113 192.168.1.36 203.97.33.231 POP Request: UIDL
19198 11:44:05.763506 203.97.33.231 192.168.1.36 POP Response: +OK unique-id listing follows
19199 11:44:05.763979 192.168.1.36 203.97.33.231 POP Request: TOP 1 0
19201 11:44:05.796370 203.97.33.231 192.168.1.36 POP [TCP Previous segment lost] Continuation
19203 11:44:05.797821 203.97.33.231 192.168.1.36 POP [TCP Out-Of-Order] Response: +OK
19205 11:44:05.874022 192.168.1.36 203.97.33.231 POP Request: RETR 1
19206 11:44:05.905740 203.97.33.231 192.168.1.36 POP Response: +OK 2398 octets
19207 11:44:05.906530 203.97.33.231 192.168.1.36 POP Continuation
19209 11:44:05.831453 192.168.1.36 203.97.33.231 POP Request: QUIT
19211 11:44:05.936231 203.97.33.231 192.168.1.36 POP Response: +OK
19221 11:44:06.018699 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop5)
19222 11:44:05.943089 192.168.1.36 203.97.33.231 POP Request: USER tomrob
19225 11:44:06.051129 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
19226 11:44:05.975524 192.168.1.36 203.97.33.231 POP Request: PASS ***
19240 11:44:06.265203 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
19241 11:44:06.189605 192.168.1.36 203.97.33.231 POP Request: QUIT
19243 11:44:06.315794 203.97.33.231 192.168.1.36 POP Response: +OK
21898 11:48:03.675783 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop5)
21899 11:48:03.750810 192.168.1.36 203.97.33.231 POP Request: USER tomrob
21901 11:48:03.708090 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
21902 11:48:03.783035 192.168.1.36 203.97.33.231 POP Request: PASS ***
21905 11:48:03.940650 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
21906 11:48:04.015627 192.168.1.36 203.97.33.231 POP Request: STAT
21907 11:48:03.989977 203.97.33.231 192.168.1.36 POP Response: +OK 1 2398
21908 11:48:04.065140 192.168.1.36 203.97.33.231 POP Request: UIDL
21909 11:48:04.023230 203.97.33.231 192.168.1.36 POP Response: +OK unique-id listing follows
21910 11:48:04.098204 192.168.1.36 203.97.33.231 POP Request: TOP 1 0
21914 11:48:04.059436 203.97.33.231 192.168.1.36 POP Response: +OK
21915 11:48:04.059469 203.97.33.231 192.168.1.36 POP Continuation
21917 11:48:04.134773 192.168.1.36 203.97.33.231 POP Request: RETR 1
21919 11:48:04.092492 203.97.33.231 192.168.1.36 POP Response: +OK 2398 octets
21920 11:48:04.093296 203.97.33.231 192.168.1.36 POP Continuation
21922 11:48:04.168693 192.168.1.36 203.97.33.231 POP Request: QUIT
21923 11:48:04.124119 203.97.33.231 192.168.1.36 POP Response: +OK
21931 11:48:04.204692 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop4)
21932 11:48:04.279662 192.168.1.36 203.97.33.231 POP Request: USER tomrob
21934 11:48:04.238047 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
21935 11:48:04.312987 192.168.1.36 203.97.33.231 POP Request: PASS ***
21943 11:48:04.449989 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
21944 11:48:04.524996 192.168.1.36 203.97.33.231 POP Request: QUIT
21945 11:48:04.501486 203.97.33.231 192.168.1.36 POP Response: +OK

Debug log from second hang at 1214. Note some messages are out of order:

Quote:

2008-03-17 12:13:09,031 [Thread-149768] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2008-03-17 12:13:09,078 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - runJob (JobPropertiesWorkFile):
2008-03-17 12:13:09,093 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - runJob(): jid=1781; wokfile created
2008-03-17 12:13:09,093 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - runJob(): start
2008-03-17 12:13:09,093 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - execProcess(): command line [C:\Program Files\Java\j2re1.4.2_16\bin\java.exe -jar jscheduler.jar /JOBFILE 1781]; work directory [C:\Program Files\24x7_Scheduler\]
2008-03-17 12:13:09,093 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - waitForProcess(): start
2008-03-17 12:13:09,093 [Thread-149898] DEBUG com.softtreetech.jscheduler.business.runner.AbstractJobRunner$TimeoutVerifier - run(): start
2008-03-17 12:13:09,093 [Thread-149898] DEBUG com.softtreetech.jscheduler.business.runner.AbstractJobRunner$TimeoutVerifier - run(): end due to zero timeout
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - waitForProcess(): end
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.AbstractJobRunner - isFailed(...) : exit code 0
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - killProcess start
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - stopExecutionImpl(): jid=1781; wokfile deleted
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - runJob(): exit code: 0
2008-03-17 12:13:10,515 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.DetachedJobRunner - runJob(): end
2008-03-17 12:13:10,562 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2008-03-17 12:13:12,078 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.JobDbImpl - updateJob(JobProperties) : start
2008-03-17 12:13:12,078 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - update(...) : start
2008-03-17 12:13:12,078 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - update(...) : end
2008-03-17 12:13:12,078 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.db.JobDbImpl - updateJob(JobProperties) : end
2008-03-17 12:14:12,453 [Thread-150067] DEBUG com.softtreetech.jscheduler.business.o0OO - checkPop() : msgs.length 1
2008-03-17 12:14:55,140 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.ui.C.void.class - show() : start
2008-03-17 12:14:55,500 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.ui.C.void.class - show() : end
2008-03-17 12:14:56,875 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.ui.C.void.class - show() : start
2008-03-17 12:14:57,234 [AWT-EventQueue-0] DEBUG com.softtreetech.jscheduler.ui.C.void.class - show() : end
12:13:10,265 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.common.util.FTPUtil - pattern after am/pm processing: YYYYMMDDHHMM.SS
2008-03-17 12:13:10,265 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - evaluateScript(): starting jsthread
2008-03-17 12:13:10,265 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - evaluateScript(): waiting
2008-03-17 12:13:10,265 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - jsthread started
2008-03-17 12:13:10,359 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptRunner - runScript: JavaScriptRunner
2008-03-17 12:13:10,375 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - jsthread stopped
2008-03-17 12:13:10,375 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): script evaluated
2008-03-17 12:13:10,375 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): stopping local js thread
2008-03-17 12:13:10,375 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - stopJScript()
2008-03-17 12:13:10,375 [Job #242 - Warehouse Hourly Finish] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): job finished
2008-03-17 12:13:10,468 [Thread-2] DEBUG com.softtreetech.jscheduler.business.H - shutdown() start
2008-03-17 12:13:10,468 [Thread-2] DEBUG com.softtreetech.jscheduler.business.runner.JobExecutorImpl - killAll() start
2008-03-17 12:13:10,468 [Thread-2] DEBUG com.softtreetech.jscheduler.business.H - shutdown() end
2008-03-17 12:29:57,968 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start

POP trace from 2nd hang:

Quote:

No. Time Source Destination Protocol Info
622 12:14:12.169953 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop6)
623 12:14:12.245511 192.168.1.36 203.97.33.231 POP Request: USER tomrob
627 12:14:12.201580 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
628 12:14:12.277105 192.168.1.36 203.97.33.231 POP Request: PASS ***
630 12:14:12.409753 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
631 12:14:12.485308 192.168.1.36 203.97.33.231 POP Request: STAT
632 12:14:12.457697 203.97.33.231 192.168.1.36 POP Response: +OK 1 2396
633 12:14:12.533355 192.168.1.36 203.97.33.231 POP Request: UIDL
634 12:14:12.492256 203.97.33.231 192.168.1.36 POP Response: +OK unique-id listing follows
635 12:14:12.567812 192.168.1.36 203.97.33.231 POP Request: TOP 1 0
637 12:14:12.525911 203.97.33.231 192.168.1.36 POP Response: +OK
638 12:14:12.525944 203.97.33.231 192.168.1.36 POP Continuation
640 12:14:12.601821 192.168.1.36 203.97.33.231 POP Request: RETR 1
641 12:14:12.558982 203.97.33.231 192.168.1.36 POP Response: +OK 2396 octets
642 12:14:12.559769 203.97.33.231 192.168.1.36 POP Continuation
644 12:14:12.635753 192.168.1.36 203.97.33.231 POP Request: QUIT
646 12:14:12.605587 203.97.33.231 192.168.1.36 POP Response: +OK
654 12:14:12.673459 203.97.33.231 192.168.1.36 POP Response: +OK POP Server (pop5)
655 12:14:12.749000 192.168.1.36 203.97.33.231 POP Request: USER tomrob
657 12:14:12.706037 203.97.33.231 192.168.1.36 POP Response: +OK password required for user tomrob@***
658 12:14:12.781560 192.168.1.36 203.97.33.231 POP Request: PASS ***
664 12:14:12.916289 203.97.33.231 192.168.1.36 POP Response: +OK Maildrop ready
665 12:14:12.991881 192.168.1.36 203.97.33.231 POP Request: QUIT
666 12:14:12.960755 203.97.33.231 192.168.1.36 POP Response: +OK

I don't see anything unusual there. The messages appear not in order because they written by multiple concurrent processes and some processes might be waiting for the log before they can write to it. Although I must admit that 1+ minute delay is pretty significant and I cannot explain it by anything other then slow performance and high CPU usage.

Let's try to figure out together where this delay comes from. I want to evaluate the effect of the email monitoring, or basically identity job(s) that cause that effect and then figure out what they are doing and how to get them run efficiently.

. Do you know if the same thing happens when you have email monitoring job enabled? If you disable this job, does the process still runs slow and out of order messages appear in the log with long delays?

The delay is definitely related to e-mail scanning. With my test job disabled (and no other e-mail trigger jobs in the system) 24x7 runs perfectly with no hangs.

When I enable the e-mail trigger job 24x7 is still fine until an e-mail comes in--then the delays/hangs start happening.

The debug logs for the last 4 hours are in chronological order. My guess was the out-of-order message was because I had to terminate 24x7 so it lost its place.

Well… if you are sure the email job is causing all troubles, the next step is to figure out if it is the job or the email trigger that are the root cause. The debug log doesn't indicate any hick-ups with the email checking, no time lags, no exceptions. Does it have a big attachment. Do you see the attachment being saved? Does the message disappear from the Inbox? And the job itself is just a test job not causing any problems?

- The attachment was only a test and < 1 k
- Neither the attachment or message were saved in the temp directory
- The message is still in the mailbox
- The job is a dummy script job--it has a single comment for the script
- According to the scheduler log, the test job never ran

Cheers

Ok. We are getting a bit closer. So that hanging is likely happening while the scheduler is trying to get unique message ids for messages in the inbox. I would like to compare your log to a log generated on my computer, but I'm not getting the same thing in WireShark.

Below is what I am getting here. Do you know what I need to do to match your output settings?

Code:

89 121.654078 192.168.1.50 192.168.0.29 POP Response: +OK Welcome to rfc1939
90 121.654450 192.168.0.29 192.168.1.50 POP Request: USER ***
91 121.715272 192.168.1.50 192.168.0.29 TCP pop3 > inova-ip [ACK] Seq=25 Ack=34 Win=5840 Len=0
92 121.716940 192.168.1.50 192.168.0.29 POP Response: +OK Password required.
93 121.717250 192.168.0.29 192.168.1.50 POP Request: PASS ***
94 121.777772 192.168.1.50 192.168.0.29 POP Response: +OK logged in.
95 121.778139 192.168.0.29 192.168.1.50 POP Request: QUIT
96 121.835537 192.168.1.50 192.168.0.29 POP Response: +OK Bye-bye.
97 121.835855 192.168.0.29 192.168.1.50 TCP inova-ip > pop3 [FIN, ACK] Seq=55 Ack=79 Win=65262 Len=0
98 121.838230 192.168.1.50 192.168.0.29 TCP pop3 > inova-ip [FIN, ACK] Seq=79 Ack=55 Win=5840 Len=0
99 121.838306 192.168.0.29 192.168.1.50 TCP inova-ip > pop3 [ACK] Seq=56 Ack=80 Win=65262 Len=0
100 121.893450 192.168.1.50 192.168.0.29 TCP pop3 > inova-ip [ACK] Seq=80 Ack=56 Win=5840 Len=0
101 179.753563 192.168.0.29 192.168.1.50 TCP pn-requester > pop3 [SYN] Seq=0 Win=64240 Len=0 MSS=1460
102 179.948174 192.168.1.50 192.168.0.29 TCP pop3 > pn-requester [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1452
103 179.948316 192.168.0.29 192.168.1.50 TCP pn-requester > pop3 [ACK] Seq=1 Ack=1 Win=65340 Len=0
104 180.006386 192.168.1.50 192.168.0.29 POP Response: +OK Welcome to rfc1939
105 180.006693 192.168.0.29 192.168.1.50 POP Request: USER ***
106 180.066231 192.168.1.50 192.168.0.29 TCP pop3 > pn-requester [ACK] Seq=25 Ack=34 Win=5840 Len=0
107 180.068355 192.168.1.50 192.168.0.29 POP Response: +OK Password required.
108 180.068809 192.168.0.29 192.168.1.50 POP Request: PASS ***
109 180.128153 192.168.1.50 192.168.0.29 POP Response: +OK logged in.
110 180.128729 192.168.0.29 192.168.1.50 POP Request: STAT
111 180.185650 192.168.1.50 192.168.0.29 POP Response: +OK 0 0
112 180.186377 192.168.0.29 192.168.1.50 POP Request: QUIT
113 180.245182 192.168.1.50 192.168.0.29 POP Response: +OK Bye-bye.
114 180.245456 192.168.1.50 192.168.0.29 TCP pop3 > pn-requester [FIN, ACK] Seq=88 Ack=61 Win=5840 Len=0
115 180.245555 192.168.0.29 192.168.1.50 TCP pn-requester > pop3 [ACK] Seq=61 Ack=89 Win=65253 Len=0
116 180.246112 192.168.0.29 192.168.1.50 TCP pn-requester > pop3 [FIN, ACK] Seq=61 Ack=89 Win=65253 Len=0
117 180.247357 192.168.0.29 192.168.1.50 TCP pn-requester2 > pop3 [SYN] Seq=0 Win=64240 Len=0 MSS=1460
118 180.389906 192.168.1.50 192.168.0.29 TCP pop3 > pn-requester [ACK] Seq=89 Ack=62 Win=5840 Len=0
119 180.443001 192.168.1.50 192.168.0.29 TCP pop3 > pn-requester2 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1452
120 180.443113 192.168.0.29 192.168.1.50 TCP pn-requester2 > pop3 [ACK] Seq=1 Ack=1 Win=65340 Len=0

I am able to reproduce [TCP Previous segment lost] Continuation and [TCP Out-Of-Order] Response: +OK things when I have my local TrendMicro Antivirus running and using local proxy to route all email messages. When TrendMicro is shutdown, I am not seeing these.

Hi there,

Here is status update for the issue related to job and queue monitors not appearing on the screen.

Our internal investigation has concluded that the issue is caused by some internal Java glitch in 1.4.03 JDK. We've recompiled the same code using 1.4.05 and it seems to be able to run job and queue monitors on all tested systems. I wonder if the email processing could be a side effect of the same issue.

I'm going to post a notice when the new private build is ready for download.

To cut down the amount in the log I set Wireshark to show only pop packets (type 'pop' into the Filter field and click Apply).

In the second column I changed the time to be absolute (I think this was in Prefs -> User Interface -> Columns).

Does that make them match?

Does your setup still work OK with TrendMicro enabled?

I'm happy to continue debugging after the next build is posted if you want.

Hmm... your output looks clean. Mine still has all these ugly TCP things like "pn-requester [ACK] Seq=89 Ack=62 Win=5840 Len=0" which appear along POP lines. That's probably because I couldn't find a filter for POP and set it for port 110. I'll try enabling just the PO.

At the moment, we are trying to address 2 issues: One is related to your email checking and another issue unrelated issue for database type jobs being experienced by other users. As soon as this 2 issues are fixed, we are going to make a public build.

The new build #253 is available for download. It is in the same place as #252. Please look for file jscheduler_253.zip

When I do the Wireshark export I turn off 'Packet details' in the Packet Format section of the dialog.

So 253 has some fixes for the e-mail scanning?

Technically there are no code changes; it is just a different build using 1.4.05 java compiler instead of 1.4.03. One of the impacts is that on 2 test computers where job and queue monitors didn't work, the started working after recompilation. Please try it. Maybe your email monitoring job will also begin working as expected.

I managed to get clean POP output in Wire shark. It still captures lots of packets but on the screen only POP protocol is displayed. The output is virtually the same as yours, but in addition I get "Request: DELE 1" following by "Response: +OK Deleted".

Can you remind again what you currently have as an email filter for the subject and text? What do you have in the actual message? Does it work for plain text email with them same simple subject and message "test" and the same text specified for email filter parameters?

Thanks for explaining, I see why you're thinking it might fix the bug now.

I've upgraded to 253.

Queue monitor button is working again now, thanks.

My e-mail subject trigger is 'trigger', the body is '*'.

I've been sending short e-mails (with a subject of 'trigger') with a body containing my signature and a tiny attachment.

After upgrading and your post:

I sent 4 messages with no attachments and 24x7 processed them correctly--saving the message body, and the POP DELE commands appeared in the Wireshark log.

I sent a message with small attachment and 24x7 hung again, without saving the message or attachment.

This is good, we're narrowing it down :-) What do you have for me to try next?

Does it happen for small text attachments?

Do you have an antivirus installed on the computer? If yes, if there an antivirus activity log or something you can check if the antivirus is involved in that issue?

A message with just a small text attachment ('.txt', no body) caused 24x7 to save the attachment into the message.txt file.

A message with a text attachment followed by some text only saved the attachment into the message.txt file (so the body was lost).

A message with some text followed by a small text attachment worked as expected by saving the message body into message.txt and the attachment into the temp directory.

I ran these tests a couple of times and 24x7 was stable throughout.

So apart from odd behaviour 24x7 handles small text attachments fine. The '.dat' files which were hanging 24x7 are really only '.txt' ones renamed.

This is all running at a hosting company (I use Remote Desktop Connection to do my work). They say the only virus checking is a daily virus scan and nothing is filtering the network traffic, but I can't be 100% sure of that.