E-Mail dependency hangs 24x7

I'm wanting to set up 24x7 to check an e-mail account and save the attachment if it finds one.

I've set up a test job, but when it runs 24x7 hangs--the GUI is unresponsive and javaw.exe is taking around 80% CPU. I've left it hung for 5+ minutes but no joy.

How can I debug this? There's nothing in the scheduler log or debug log.

Thanks.

24x7 multi-platform edition 4.1 247, under XP.

UPDATE: Hold that thought (there doesn't seem to be a way to delete a posting). Using telnet to retrieve mail is acting weird, I'll check that out first.

Hi,

What is the last message appearing in the debug log? when it hangs with high CPU usage.

I'm assuming that the tracing option in 24x7 is enabled at the moment and POP3 communication is not blocked by a firewall or something else.

I've got trace enabled but nothing appears in the debug log or scheduler log.

The provider hosting our machine has opened the firewall but I think there's issues with it. If I telnet to the mail server the connection acts like 'return' is being hit all the time. I can telnet from my own machine fine.

e.g., when I try to login as healthstat:

	Code:
	+OK lavad user he-ERR Invalid USER command. ealth-ERR Unrecognized command.

So the problem appears to be with the hosting service, but 24x7 isn't handling the error gracefully.

I've got a call in with the hosting service, I'll let you know.

Thanks for the status update.

FYI: 24x7 Multi-platform version is using standard Java mail packages. It is not doing anything fancy there. If the cause of the problem can be identified, we can check for mail package fixes and/or known workarounds.

For now it is not yet clear where this process gets stuck. If you are running it on Unix system and know how to use tcpdump utility, you can capture the TCP traffic on POP3 port and all internal commands executed during the communication process. On Windows system you can try using Ethereal utility http://www.ethereal.com/ which provides a graphical equivalent of tcpdump.

Thanks for the info.

The hosting service can't tell me what's going on, and it works from a different mail server so I'll just go with that.

But now I can't get 24x7 to process the message.

I've set an email trigger, set both the subject and text to 'process'. I've told it to save attachments.

I sent a message with both subject and body set to 'process'. I've tried with and without attachments. Nothing appears in the temporary directory--or anywhere else that I can see.

%TEMP% is C:\DOCUME~1\CBG.TOM\LOCALS~1\Temp

What have I missed?

Here's the debug log:

Code:

2008-03-01 16:15:28,781 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2008-03-01 16:15:28,781 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=15135
2008-03-01 16:15:28,781 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2008-03-01 16:15:28,781 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2008-03-01 16:15:29,109 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2008-03-01 16:15:29,203 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2008-03-01 16:15:29,625 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : loading job db
2008-03-01 16:15:29,640 [main] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - buildIndex(): totalRecordsNumber: 250
2008-03-01 16:15:29,640 [main] DEBUG com.softtreetech.jscheduler.db.drivers.file.FileJobDbStorage - buildIndex(): deletedRecordsNumber: 40
2008-03-01 16:15:29,671 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : job on demand: loading workfile
2008-03-01 16:15:29,687 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : job on demand: deleting workfile
2008-03-01 16:15:29,687 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : job on demand: running
2008-03-01 16:15:29,687 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): script: // nothing
2008-03-01 16:15:29,687 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): starting JavaScript
2008-03-01 16:15:29,687 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): job not using user authentication
2008-03-01 16:15:29,734 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.common.util.FTPUtil - converting pattern:YYYYMMDDHHMM.SS
2008-03-01 16:15:29,734 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.common.util.FTPUtil - pattern after am/pm processing: YYYYMMDDHHMM.SS
2008-03-01 16:15:29,734 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - evaluateScript(): starting jsthread
2008-03-01 16:15:29,734 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - evaluateScript(): waiting
2008-03-01 16:15:29,734 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - jsthread started
2008-03-01 16:15:29,828 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptRunner - runScript: JavaScriptRunner
2008-03-01 16:15:29,859 [JavaScript] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - jsthread stopped
2008-03-01 16:15:29,859 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): script evaluated
2008-03-01 16:15:29,859 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): stopping local js thread
2008-03-01 16:15:29,859 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.javascript.JavaScriptThreadImpl - stopJScript()
2008-03-01 16:15:29,859 [Job #166 - pop test] DEBUG com.softtreetech.jscheduler.business.runner.JavaScriptJobRunner - runJob(): job finished
2008-03-01 16:15:29,953 [Thread-2] DEBUG com.softtreetech.jscheduler.business.OooO - shutdown() start
2008-03-01 16:15:29,953 [Thread-2] DEBUG com.softtreetech.jscheduler.business.runner.JobExecutorImpl - killAll() start
2008-03-01 16:15:29,953 [Thread-2] DEBUG com.softtreetech.jscheduler.business.OooO - shutdown() end

Email messages often contain non-printable characters. For example, line wraps, html formatting and tags. What appears on the screen as a simple "process" word in the message body can look quite different. The message text is compared to the email job trigger as is, just as it is downloaded from the email server.

I suggest to add * wildcards to the end of the process* text or for beginning start with a simple job that matches incoming emails by subject only and for the message text uses * wildcard without double quotes. The * wildcard means any text in place of the wildcard.

Hope this helps.

Good tip about the asterisk thanks, you should add it to the manual :-)

It's still not working though...

It is in the manual somewhere.

Sorry I didn't get your first post correctly. If I read the log properly, the scheduler found the required message because it started the job. So the issue is not the message subject or text, the issue is where the attachments go. Normally they should be saved in system temp directory, on Windows, C:\TEMP or similar. You can customize this location if you add -Djava.io.tmpdir=C:\mydir to the schedule command line in master.bat file..

By the way, you are not trying to start that job manually. Are you? If you run it manually (post trigger processing), no attachments will be saved. Attachments are saved at the time when the scheduler finds required message on the email server, not when the job is run.

Sorry, I was running the job manually. I understand now ;-)

Ethreal has been replaced by Wireshark. There's a 'TCP error' (maybe from Wireshark?), and 24x7 seems to be logging on twice--I don't know if this is relevant.

I've got the subject test set to 'process' and the text to '*'. The e-mail text and attachments still aren't being saved--though it looks like 24x7 is retrieving them?

With nothing in mailbox:

Code:

5353 12:20:54.91 Response: +OK POP Server (pop4)
5354 12:20:54.91 Request: USER tomrob
5357 12:20:54.94 Response: +OK password required for user tomrob@***
5358 12:20:54.94 Request: PASS ***
5361 12:20:55.15 Response: +OK Maildrop ready
5362 12:20:55.15 Request: STAT
5364 12:20:55.20 Response: +OK 0 0
5365 12:20:55.20 Request: QUIT
5367 12:20:55.23 Response: +OK
5375 12:20:55.31 Response: +OK POP Server (pop4)
5376 12:20:55.31 Request: USER tomrob
5378 12:20:55.34 Response: +OK password required for user tomrob@***
5379 12:20:55.34 Request: PASS ***
5381 12:20:55.54 Response: +OK Maildrop ready
5382 12:20:55.54 Request: QUIT
5383 12:20:55.59 Response: +OK

Message which should have triggered the job:

Code:

9181 12:26:08.59 Response: +OK POP Server (pop5)
9182 12:26:08.61 Request: USER tomrob
9184 12:26:08.63 Response: +OK password required for user tomrob@***
9185 12:26:08.64 Request: PASS ***
9191 12:26:08.83 Response: +OK Maildrop ready
9192 12:26:08.85 Request: STAT
9194 12:26:08.88 Response: +OK 1 2346
9196 12:26:08.92 Request: UIDL
9198 12:26:08.94 Response: +OK unique-id listing follows
9199 12:26:08.96 Request: TOP 1 0
9200 12:26:08.97 [TCP Previous segment lost] Continuation
9202 12:26:08.98 [TCP Out-Of-Order] Response: +OK
9204 12:26:09.02 Request: RETR 1
9206 12:26:09.05 Response: +OK 2346 octets
9207 12:26:09.05 Continuation
9209 12:26:09.08 Request: QUIT
9210 12:26:09.10 Response: +OK
9218 12:26:09.17 Response: +OK POP Server (pop4)
9219 12:26:09.18 Request: USER tomrob
9222 12:26:09.20 Response: +OK password required for user tomrob@***
9223 12:26:09.21 Request: PASS ***
9246 12:26:09.41 Response: +OK Maildrop ready
9247 12:26:09.42 Request: QUIT
9249 12:26:09.46 Response: +OK

Looking at the same message again at next poll:

Code:

10909 12:28:08.61 Response: +OK POP Server (pop6)
10910 12:28:08.61 Request: USER tomrob
10913 12:28:08.65 Response: +OK password required for user tomrob@***
10914 12:28:08.64 Request: PASS ***
10926 12:28:08.85 Response: +OK Maildrop ready
10927 12:28:08.85 Request: STAT
10929 12:28:08.89 Response: +OK 1 2346
10930 12:28:08.89 Request: UIDL
10931 12:28:08.94 Response: +OK unique-id listing follows
10932 12:28:08.94 Request: QUIT
10936 12:28:08.97 Response: +OK
10944 12:28:09.05 Response: +OK POP Server (pop4)
10945 12:28:09.05 Request: USER tomrob
10947 12:28:09.08 Response: +OK password required for user tomrob@***
10948 12:28:09.08 Request: PASS ***
10952 12:28:09.29 Response: +OK Maildrop ready
10953 12:28:09.29 Request: QUIT
10961 12:28:09.34 Response: +OK

Another new message which should have triggered the job--to see if the TCP error is repeated:

Code:

12932 12:30:08.58 Response: +OK POP Server (pop6)
12933 12:30:08.60 Request: USER tomrob
12936 12:30:08.62 Response: +OK password required for user tomrob@***
12937 12:30:08.63 Request: PASS ***
12939 12:30:08.82 Response: +OK Maildrop ready
12940 12:30:08.83 Request: STAT
12941 12:30:08.86 Response: +OK 2 4692
12942 12:30:08.88 Request: UIDL
12943 12:30:08.91 Response: +OK unique-id listing follows
12944 12:30:08.92 Request: TOP 2 0
12946 12:30:08.94 [TCP Previous segment lost] Continuation
12948 12:30:08.95 [TCP Out-Of-Order] Response: +OK
12951 12:30:08.95 Request: RETR 2
12953 12:30:08.99 Response: +OK 2346 octets
12954 12:30:08.99 Continuation
12956 12:30:09.01 Request: QUIT
12957 12:30:09.04 Response: +OK
12965 12:30:09.12 Response: +OK POP Server (pop6)
12966 12:30:09.13 Request: USER tomrob
12968 12:30:09.15 Response: +OK password required for user tomrob@***
12969 12:30:09.16 Request: PASS ***
12989 12:30:09.35 Response: +OK Maildrop ready
12990 12:30:09.37 Request: QUIT
12991 12:30:09.40 Response: +OK

Interesting... I don't see it downloading new emails at all. The closest thing is

	Code:
	9196 12:26:08.92 Request: UIDL 9198 12:26:08.94 Response: +OK unique-id listing follows 9199 12:26:08.96 Request: TOP 1 0 9200 12:26:08.97 [TCP Previous segment lost] Continuation 9202 12:26:08.98 [TCP Out-Of-Order] Response: +OK 9204 12:26:09.02 Request: RETR 1 9206 12:26:09.05 Response: +OK 2346 octets 9207 12:26:09.05 Continuation 9209 12:26:09.08 Request: QUIT

Here I see a request for email messages Id listing returning strange "TCP Previous segment lost" message which is following by another strange response "TCP Out-Of-Order" following by a retry attempt and then giving up.

I'll try to get Wireshark installed on my system and check what I get in the traffic log for our email server communication.

Here is my status update. I was getting similar "TCP Previous segment lost" messages until I disabled my local antivirus program which was attempting to proxy all net traffic and somehow filter pop and smtp traffic (ports 110 and 25 respectively), before it riches other programs.

Now, I discovered that * wildcard symbol doesn't work for me. It works in the Windows version, but not in the Multi-platform. To make the Multi-platform version find my email, I had to specify exact text for the subject and message "test" and "test" and send a plain text email to myself.

I will find out tomorrow which wildcard symbols are used in the Multi-platform version

Bump... did you find the wildcards?

Oops.. I forgot to post the response that I got 2 days ago. Sorry I got bad news. The multi-platform version of 24x7 currently doesn't support wildcards in email triggers. The subject/message text in the job settings must be entered exactly as it appears in the email message. Yet, all leading and trailing spaces appearing in the checked email messages are ignored during email comparison.

I was under impression that "*" wildcards are supported in both multi-platform and Windows versions.

Ok, Now I've got some good news for you. You should receive an email from our support account with a download link to the private build 4.1.252. This is the latest build which we are still testing and which supports a number of email handling enhancements. . I'm going to post the complete list of changes in the dedicated "versions" topic.

For the email handling, this build introduces support for "*" wildcards in the subject and text body, actually this what I expected being already available in older builds, but it was not. It also support regular expressions in the email triggers and also supports automatic email deletion of read emails in order to reduce email scanning and processing time in automated systems where nobody checks and deletes the email manually. In older builds emails are not deleted, and if left forever on the server, they cause gradual increase in processing times as the number of emails in inbox grows up. When number of inbox emails reaches tens of thousands the processing slows down to a crawl and it may take hours for the new email to be processed. Hope this issue is gone forever.

Thanks (and to Dmitriy) for access to the beta.

We're getting somewhere, which is great.

There's still a few issues:

- I had success saving '.dat' attachments but not '.txt' ones--the message itself would be saved but not the attachment.

- 24x7 managed to process a few messages and then hung again

- 24x7 is deleting *all* read messages from the POP server. I think it should only delete ones which match the criteria, or if not, you need to really spell this out.

Cheers