Menu ▾ ▴

#206 JVM Event email hangs and does not send

v3.3.0
closed-fixed
Leif Mortenson
Event (3)
5
2008-12-22
2008-08-21
Anonymous
No

Hi,

I am trying to implement monitoring of the status of the JVM inside the wrapper using the Professional V 3.3.0 32 bit wrapper.

It connects to the smtp server but when it tries to send a startup email this does not appear to work. In fact it is still trying to send it when I shut the Service down and the Service sits there forever with a PENDING STOP status forcing a reboot of the machine to clear. I have set logging to DEBUG but that has not given me any more clues.

Strangely enough the Java application it is running (and who's purpose is actually to send alerting emails as a result of other failures) uses exactly the same smtp server to send startup and closedown emails quite successfully.

The settings I have put in the wrapper.conf file are:

wrapper.event.default.email.debug=debug
wrapper.event.default.email.smtp.host=mailrelay.ea.unisys.com
wrapper.event.default.email.smtp.port=25
wrapper.event.default.email.subject=[%WRAPPER_HOSTNAME%:%WRAPPER_NAME%:%WRAPPER_EVENT_NAME%] eServe Windows Java Service Event Notification
wrapper.event.default.email.sender=eServeDev@unisys.com
wrapper.event.default.email.recipient=mark.vincent@unisys.com

# Event specific settings.
wrapper.event.jvm_start.email=TRUE
wrapper.event.jvm_start.email.body=The wrapper JVM was started.\n\nPlease check on its status.\n

As the ability to do this was the reason we bought the Server licences this is a major impediment. I have attached a wrapper log as an example (the app successfully sends an email via the same smtp server while processing).

My email address is mark.vincent@unisys.com

Thank you,
Mark Vincent.

Discussion

  • Nobody/Anonymous

    Nobody/Anonymous - 2008-08-21

    Debug Wrapper Log

     
    wrapper-AlertEmail.log

  • Mark Vincent

    Mark Vincent - 2008-08-21

    Logged In: YES
    user_id=2189007
    Originator: NO

    I have just seen this error in the wrapper log as it was trying to close and I thought it might be pertinent:

    INFO | wrapper | 2008/08/21 15:29:36 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:38 | Recv:
    ERROR | wrapper | 2008/08/21 15:29:38 | Unable to send mail for jvm_start event: Unexpected SMTP code from server:

    I hope this helps a little (it would have been good if it had reported what the unexpected SMTP Code was though).

    Regards,
    Mark.

     

  • Leif Mortenson

    Leif Mortenson - 2008-08-22

    Logged In: YES
    user_id=228081
    Originator: NO

    Mark,
    We are actively investigating this issue. The mail servers we normally use for testing do not have this problem. But there is obviously something different about your server which is causing a problem.

    I have a few requests which will help us to resolve this quickly.
    1) Do you which mail server you are using to send mails? ie. The SMTP software running on mailrelay.ea.unisys.com

    2) The log fragment you sent below is useful, but I am also interested in any other output in the log. Could you please attach the full wrapper.log file showing a single wrapper invocation at the bottom of this issue? This should include the answer to #1.

    The message that you posted in your followup message:
    ---
    Unable to send mail for jvm_start event: Unexpected SMTP code from server:
    ---
    The Wrapper normally always displays the unexpected code. But in the case of your server, it appears that a blank line was received.

    We are making some changes to the code to add configurable timeouts on the reads from the server, and to improve the quality of the debug log output.

    In the mean time, could you please send me the full log file?

    Cheers,
    Leif

     

  • Leif Mortenson

    Leif Mortenson - 2008-08-22
    • milestone: --> v3.3.0
    • assigned_to: nobody --> mortenson
    • status: open --> open-accepted
     

  • Mark Vincent

    Mark Vincent - 2008-08-22

    Logged In: YES
    user_id=2189007
    Originator: NO

    Hi Leif,

    I did upload the whole log file but anyway here is the bulk of the wrapper log:

    STATUS | wrapper | 2008/08/21 14:35:54 | Starting the eServe Alert Email service...
    STATUS | wrapper | 2008/08/21 14:35:54 | --> Wrapper Started as Service
    STATUS | wrapper | 2008/08/21 14:35:54 | Java Service Wrapper Professional Edition 3.3.0
    STATUS | wrapper | 2008/08/21 14:35:54 | Copyright (C) 1999-2008 Tanuki Software, Inc. All Rights Reserved.
    STATUS | wrapper | 2008/08/21 14:35:54 | http://wrapper.tanukisoftware.org
    STATUS | wrapper | 2008/08/21 14:35:54 | Licensed to Unisys European Services Limited (Dev Server)
    STATUS | wrapper | 2008/08/21 14:35:54 |
    STATUS | wrapper | 2008/08/21 14:35:54 | Launching a JVM...
    INFO | wrapper | 2008/08/21 14:35:54 | Opening connection to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 14:35:54 | jvm_start event mail: Connected to mailrelay.ea.unisys.com:25.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: WrapperManager class initialized by thread: main Using classloader: sun.misc.Launcher$AppClassLoader@a39137
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager: Initializing...
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: JVM #1
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Running a 32-bit JVM.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Registering shutdown hook
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Using wrapper
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Load native library. One or more attempts may fail if platform specific libraries do not exist. This is NORMAL and is only a problem if they all fail.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Unable to load native library: wrapper-windows-x86-32.dll Cause: no wrapper-windows-x86-32 in java.library.path
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Loaded native library: wrapper.dll
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Calling native initialization method.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperJNI Debug: Initializing WrapperManager native library.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperJNI Debug: Java Executable: C:\Java\j2sdk1.5.0_14\bin\java.exe
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperJNI Debug: Windows version: 5.1.2600
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Java Version : 1.5.0_14-b03 Java HotSpot(TM) Client VM
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Java VM Vendor : Sun Microsystems Inc.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug:
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Control event monitor thread started.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Startup runner thread started.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: WrapperManager.start(eService.Main@eb7859, args["AlertEmail", "../Logs", "DEBUG", "192.168.0.195", "Mark10G", "mark", "mev", "mailrelay.ea.unisys.com", "usea-exch7.na.uis.unisys.com", "NA\\eservedev1", "October16project"]) called by thread: main
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Communications runner thread started.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Open socket to wrapper...Wrapper-Connection
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Opened Socket from 31000 to 32000
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Send a packet KEY : 2Q-bg7IML9XR4YHye8wVn3pcPaKRxyqw
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: handleSocket(Socket[addr=/127.0.0.1,port=32000,localport=31000])
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Received a packet LOW_LOG_LEVEL : 1
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: LowLogLevel from Wrapper is 1
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Received a packet PING_TIMEOUT : 30
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: PingTimeout from Wrapper is 30000
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Received a packet PROPERTIES : (Property Values)
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Received a packet START : start
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: calling WrapperListener.start()
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: Waiting for WrapperListener.start runner thread to complete.
    INFO | jvm 1 | 2008/08/21 14:35:55 | WrapperManager Debug: WrapperListener.start runner thread started.
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service Starting
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. No Args = 11
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Application Name = AlertEmail
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Log Path = ../Logs
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Level of Logging = DEBUG
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Database Host = 192.168.0.195
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Database SID = Mark10G
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Database Usercode = mark
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. Database Password = mev
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. SMTP Email Server = mailrelay.ea.unisys.com
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. POP3 Email Server = usea-exch7.na.uis.unisys.com
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. POP3 Usercode = NA\\eservedev1
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service. POP3 Password = October16project
    INFO | jvm 1 | 2008/08/21 14:35:55 | eServe Alert Email Windows Service being Started
    INFO | jvm 1 | 2008/08/21 14:35:55 | Getting Database Connection for Alert Email ...
    INFO | jvm 1 | 2008/08/21 14:35:55 | Alert Email Custom Database Connection specified: jdbc:oracle:thin:@192.168.0.195:1521:Mark10G
    INFO | wrapper | 2008/08/21 14:35:55 | Recv: 220 ih85.ea.unisys.com ESMTP Sendmail 8.12.11/8.12.11; Thu, 21 Aug 2008 13:35:55 GMT
    INFO | wrapper | 2008/08/21 14:35:55 | Send: HELO localhost
    INFO | jvm 1 | 2008/08/21 14:35:56 | eServe got Database Connection for Alert Email
    INFO | jvm 1 | 2008/08/21 14:35:56 | eServe Alert Email Worker initialising
    INFO | jvm 1 | 2008/08/21 14:35:56 | Loading ChilKat Email Library
    INFO | wrapper | 2008/08/21 14:35:56 | Recv: 250 ih85.ea.unisys.com Hello [172.23.4.81], pleased to meet you
    INFO | wrapper | 2008/08/21 14:35:56 | Send: MAIL FROM: <eServeDev@unisys.com>
    INFO | wrapper | 2008/08/21 14:35:56 | Recv: 250 2.1.0 <eServeDev@unisys.com>... Sender ok
    INFO | wrapper | 2008/08/21 14:35:56 | Send: RCPT TO: <jerry.justman@unisys.com>
    INFO | wrapper | 2008/08/21 14:35:57 | Recv: 250 2.1.5 <jerry.justman@unisys.com>... Recipient ok
    INFO | wrapper | 2008/08/21 14:35:57 | Send: DATA
    INFO | wrapper | 2008/08/21 14:35:57 | Recv: 354 Please start mail input.
    INFO | wrapper | 2008/08/21 14:35:57 | Send: From: eServeDev@unisys.com
    INFO | wrapper | 2008/08/21 14:35:57 | Send: To: jerry.justman@unisys.com
    INFO | wrapper | 2008/08/21 14:35:57 | Send: Subject: [GBHB-VINCENTME:eServeAlertEmail:jvm_start] eServe Windows Java Service Event Notification
    INFO | wrapper | 2008/08/21 14:35:57 | Send: Date: Fri, 13 Apr 2007 03:02:00 +0900
    INFO | wrapper | 2008/08/21 14:35:57 | Send: X-Mailer: Java Service Wrapper Professional 3.3.0
    INFO | wrapper | 2008/08/21 14:35:57 | Send:
    INFO | wrapper | 2008/08/21 14:35:57 | Send: The wrapper JVM was started.\n\nPlease check on its status.\n
    INFO | wrapper | 2008/08/21 14:35:57 | Send: .
    INFO | jvm 1 | 2008/08/21 14:35:57 | Create Email loaded ChilKat Library and connected to SMTP Server: mailrelay.ea.unisys.com
    INFO | jvm 1 | 2008/08/21 14:35:57 | eServe Alert Email AlertEmail initialising
    INFO | jvm 1 | 2008/08/21 14:35:57 | eServe Alert Email AlertEmail initialised. Trans ID # 27000.0
    INFO | jvm 1 | 2008/08/21 14:35:57 | eServe Alert Email Worker initialised
    INFO | jvm 1 | 2008/08/21 14:35:57 | WrapperManager Debug: WrapperListener.start runner thread stopped.
    INFO | jvm 1 | 2008/08/21 14:35:57 | WrapperManager Debug: returned from WrapperListener.start()
    INFO | jvm 1 | 2008/08/21 14:35:57 | WrapperManager Debug: Send a packet STARTED :
    INFO | jvm 1 | 2008/08/21 14:35:57 | eServe Alert Email Worker now running
    INFO | jvm 1 | 2008/08/21 14:35:57 | WrapperManager Debug: Startup runner thread stopped.
    INFO | jvm 1 | 2008/08/21 14:35:57 | eServe Alert Email Application Version: 1.01 now running (Services Library Version: 1.07)
    INFO | jvm 1 | 2008/08/21 14:35:58 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:35:58 | WrapperManager Debug: Send a packet PING : ping
    STATUS | wrapper | 2008/08/21 14:35:59 | eServe Alert Email started.
    INFO | jvm 1 | 2008/08/21 14:36:00 | Email Message sent from eServeDev@unisys.com to markvin@btinternet.com. mark.vincent@gb.unisys.com.
    INFO | jvm 1 | 2008/08/21 14:36:02 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:36:02 | WrapperManager Debug: Send a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:36:06 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:41:03 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:41:03 | WrapperManager Debug: Send a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:41:07 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 14:41:07 | WrapperManager Debug: Send a packet PING : ping
    STATUS | wrapper | 2008/08/21 14:41:11 | Stopping the eServe Alert Email service...
    INFO | jvm 1 | 2008/08/21 14:41:11 | WrapperManager Debug: Received a packet SERVICE_CONTROL_CODE : 1
    INFO | jvm 1 | 2008/08/21 14:41:11 | WrapperManager Debug: ServiceControlCode from Wrapper with code 1
    INFO | wrapper | 2008/08/21 14:41:16 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:21 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:26 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:31 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:36 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:41 | Waiting to stop...
    INFO | jvm 1 | 2008/08/21 14:41:41 | WrapperManager Debug: Read Timed out. (Last Ping was 33500 milliseconds ago)
    INFO | jvm 1 | 2008/08/21 14:41:41 | WrapperManager: The Wrapper code did not ping the JVM for 33 seconds. Quit and let the Wrapper resynch.
    INFO | jvm 1 | 2008/08/21 14:41:41 | WrapperManager Debug: Send a packet RESTART : restart
    STATUS | wrapper | 2008/08/21 14:41:41 | JVM requested a restart.
    INFO | jvm 1 | 2008/08/21 14:41:42 | WrapperManager Debug: Thread, Wrapper-Connection, handling the shutdown process.
    INFO | jvm 1 | 2008/08/21 14:41:42 | WrapperManager Debug: calling listener.stop()
    INFO | jvm 1 | 2008/08/21 14:41:42 | WrapperManager Debug: Waiting for WrapperListener.stop runner thread to complete.
    INFO | jvm 1 | 2008/08/21 14:41:42 | WrapperManager Debug: WrapperListener.stop runner thread started.
    INFO | jvm 1 | 2008/08/21 14:41:42 | eServe Alert Email Windows Service being Stopped
    INFO | wrapper | 2008/08/21 14:41:46 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:51 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:41:56 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:01 | Waiting to stop...
    INFO | jvm 1 | 2008/08/21 14:42:04 | Email Message sent from eServeDev@unisys.com to markvin@btinternet.com. mark.vincent@gb.unisys.com.
    INFO | jvm 1 | 2008/08/21 14:42:04 | WrapperManager Debug: WrapperListener.stop runner thread stopped.
    INFO | jvm 1 | 2008/08/21 14:42:04 | WrapperManager Debug: returned from listener.stop() -> 1
    INFO | jvm 1 | 2008/08/21 14:42:04 | WrapperManager Debug: shutdownJVM(1) Thread:Wrapper-Connection
    INFO | jvm 1 | 2008/08/21 14:42:04 | WrapperManager Debug: Send a packet STOPPED : 1
    INFO | wrapper | 2008/08/21 14:42:06 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:11 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:16 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:21 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:26 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:31 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:36 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:42:41 | Waiting to stop...
    INFO | wrapper | 2008/08/21 14:51:14 | Recv:
    ERROR | wrapper | 2008/08/21 14:51:14 | Unable to send mail for jvm_start event: Unexpected SMTP code from server:
    INFO | wrapper | 2008/08/21 14:51:14 | Opening connection to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 14:51:14 | jvm_stop event mail: Connected to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 14:51:15 | Recv: 220 ih85.ea.unisys.com ESMTP Sendmail 8.12.11/8.12.11; Thu, 21 Aug 2008 13:51:15 GMT
    INFO | wrapper | 2008/08/21 14:51:15 | Send: HELO localhost
    INFO | wrapper | 2008/08/21 14:51:15 | Recv: 250 ih85.ea.unisys.com Hello [172.23.4.81], pleased to meet you
    INFO | wrapper | 2008/08/21 14:51:15 | Send: MAIL FROM: <eServeDev@unisys.com>
    INFO | wrapper | 2008/08/21 14:51:16 | Recv: 250 2.1.0 <eServeDev@unisys.com>... Sender ok
    INFO | wrapper | 2008/08/21 14:51:16 | Send: RCPT TO: <jerry.justman@unisys.com>
    INFO | wrapper | 2008/08/21 14:51:16 | Recv: 250 2.1.5 <jerry.justman@unisys.com>... Recipient ok
    INFO | wrapper | 2008/08/21 14:51:16 | Send: DATA
    INFO | wrapper | 2008/08/21 14:51:16 | Recv: 354 Please start mail input.
    INFO | wrapper | 2008/08/21 14:51:16 | Send: From: eServeDev@unisys.com
    INFO | wrapper | 2008/08/21 14:51:16 | Send: To: jerry.justman@unisys.com
    INFO | wrapper | 2008/08/21 14:51:16 | Send: Subject: [GBHB-VINCENTME:eServeAlertEmail:jvm_stop] eServe Windows Java Service Event Notification
    INFO | wrapper | 2008/08/21 14:51:16 | Send: Date: Fri, 13 Apr 2007 03:02:00 +0900
    INFO | wrapper | 2008/08/21 14:51:16 | Send: X-Mailer: Java Service Wrapper Professional 3.3.0
    INFO | wrapper | 2008/08/21 14:51:16 | Send:
    INFO | wrapper | 2008/08/21 14:51:16 | Send: The wrapper JVM was stopped.\n\nPlease check on its status.\n
    INFO | wrapper | 2008/08/21 14:51:16 | Send: .
    INFO | wrapper | 2008/08/21 15:06:36 | Recv:
    ERROR | wrapper | 2008/08/21 15:06:36 | Unable to send mail for jvm_stop event: Unexpected SMTP code from server:
    WARN | wrapper | 2008/08/21 15:06:36 | JVM exited unexpectedly while stopping the application.
    STATUS | wrapper | 2008/08/21 15:06:36 | <-- Wrapper Stopped
    STATUS | wrapper | 2008/08/21 15:14:16 | Starting the eServe Alert Email service...
    STATUS | wrapper | 2008/08/21 15:14:16 | --> Wrapper Started as Service
    STATUS | wrapper | 2008/08/21 15:14:16 | Java Service Wrapper Professional Edition 3.3.0
    STATUS | wrapper | 2008/08/21 15:14:16 | Copyright (C) 1999-2008 Tanuki Software, Inc. All Rights Reserved.
    STATUS | wrapper | 2008/08/21 15:14:16 | http://wrapper.tanukisoftware.org
    STATUS | wrapper | 2008/08/21 15:14:16 | Licensed to Unisys European Services Limited (Dev Server)
    STATUS | wrapper | 2008/08/21 15:14:16 |
    STATUS | wrapper | 2008/08/21 15:14:16 | Launching a JVM...
    INFO | wrapper | 2008/08/21 15:14:16 | Opening connection to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 15:14:16 | jvm_start event mail: Connected to mailrelay.ea.unisys.com:25.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: WrapperManager class initialized by thread: main Using classloader: sun.misc.Launcher$AppClassLoader@a39137
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager: Initializing...
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: JVM #1
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Running a 32-bit JVM.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Registering shutdown hook
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Using wrapper
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Load native library. One or more attempts may fail if platform specific libraries do not exist. This is NORMAL and is only a problem if they all fail.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Unable to load native library: wrapper-windows-x86-32.dll Cause: no wrapper-windows-x86-32 in java.library.path
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Loaded native library: wrapper.dll
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Calling native initialization method.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperJNI Debug: Initializing WrapperManager native library.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperJNI Debug: Java Executable: C:\Java\j2sdk1.5.0_14\bin\java.exe
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperJNI Debug: Windows version: 5.1.2600
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Java Version : 1.5.0_14-b03 Java HotSpot(TM) Client VM
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Java VM Vendor : Sun Microsystems Inc.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug:
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Control event monitor thread started.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Startup runner thread started.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: WrapperManager.start(eService.Main@eb7859, args["AlertEmail", "../Logs", "DEBUG", "192.168.0.195", "Mark10G", "mark", "mev", "mailrelay.ea.unisys.com", "usea-exch7.na.uis.unisys.com", "NA\\eservedev1", "October16project"]) called by thread: main
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Communications runner thread started.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Open socket to wrapper...Wrapper-Connection
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Opened Socket from 31000 to 32000
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Send a packet KEY : hW_GT_m7JfyXnmJA-DeNNbIkdo42BUfR
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: handleSocket(Socket[addr=/127.0.0.1,port=32000,localport=31000])
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Received a packet LOW_LOG_LEVEL : 1
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: LowLogLevel from Wrapper is 1
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Received a packet PING_TIMEOUT : 30
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: PingTimeout from Wrapper is 30000
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Received a packet PROPERTIES : (Property Values)
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Received a packet START : start
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: calling WrapperListener.start()
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: Waiting for WrapperListener.start runner thread to complete.
    INFO | jvm 1 | 2008/08/21 15:14:16 | WrapperManager Debug: WrapperListener.start runner thread started.
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service Starting
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. No Args = 11
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Application Name = AlertEmail
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Log Path = ../Logs
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Level of Logging = DEBUG
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Database Host = 192.168.0.195
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Database SID = Mark10G
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Database Usercode = mark
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. Database Password = mev
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. SMTP Email Server = mailrelay.ea.unisys.com
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. POP3 Email Server = usea-exch7.na.uis.unisys.com
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. POP3 Usercode = NA\\eservedev1
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service. POP3 Password = October16project
    INFO | jvm 1 | 2008/08/21 15:14:16 | eServe Alert Email Windows Service being Started
    INFO | jvm 1 | 2008/08/21 15:14:16 | Getting Database Connection for Alert Email ...
    INFO | jvm 1 | 2008/08/21 15:14:16 | Alert Email Custom Database Connection specified: jdbc:oracle:thin:@192.168.0.195:1521:Mark10G
    INFO | jvm 1 | 2008/08/21 15:14:17 | eServe got Database Connection for Alert Email
    INFO | jvm 1 | 2008/08/21 15:14:17 | eServe Alert Email Worker initialising
    INFO | jvm 1 | 2008/08/21 15:14:17 | Loading ChilKat Email Library
    INFO | wrapper | 2008/08/21 15:14:17 | Recv: 220 ih85.ea.unisys.com ESMTP Sendmail 8.12.11/8.12.11; Thu, 21 Aug 2008 14:14:17 GMT
    INFO | wrapper | 2008/08/21 15:14:17 | Send: HELO localhost
    INFO | wrapper | 2008/08/21 15:14:17 | Recv: 250 ih85.ea.unisys.com Hello [172.23.4.81], pleased to meet you
    INFO | wrapper | 2008/08/21 15:14:17 | Send: MAIL FROM: <eServeDev@unisys.com>
    INFO | wrapper | 2008/08/21 15:14:18 | Recv: 250 2.1.0 <eServeDev@unisys.com>... Sender ok
    INFO | wrapper | 2008/08/21 15:14:18 | Send: RCPT TO: <mark.vincent@unisys.com>
    INFO | jvm 1 | 2008/08/21 15:14:18 | Create Email loaded ChilKat Library and connected to SMTP Server: mailrelay.ea.unisys.com
    INFO | jvm 1 | 2008/08/21 15:14:18 | eServe Alert Email AlertEmail initialising
    INFO | jvm 1 | 2008/08/21 15:14:18 | eServe Alert Email AlertEmail initialised. Trans ID # 27001.0
    INFO | jvm 1 | 2008/08/21 15:14:18 | eServe Alert Email Worker initialised
    INFO | jvm 1 | 2008/08/21 15:14:18 | WrapperManager Debug: WrapperListener.start runner thread stopped.
    INFO | jvm 1 | 2008/08/21 15:14:18 | WrapperManager Debug: returned from WrapperListener.start()
    INFO | jvm 1 | 2008/08/21 15:14:18 | WrapperManager Debug: Send a packet STARTED :
    INFO | jvm 1 | 2008/08/21 15:14:18 | eServe Alert Email Worker now running
    INFO | jvm 1 | 2008/08/21 15:14:18 | eServe Alert Email Application Version: 1.01 now running (Services Library Version: 1.07)
    INFO | jvm 1 | 2008/08/21 15:14:18 | WrapperManager Debug: Startup runner thread stopped.
    INFO | wrapper | 2008/08/21 15:14:19 | Recv: 250 2.1.5 <mark.vincent@unisys.com>... Recipient ok
    INFO | wrapper | 2008/08/21 15:14:19 | Send: DATA
    INFO | wrapper | 2008/08/21 15:14:19 | Recv: 354 Please start mail input.
    INFO | wrapper | 2008/08/21 15:14:19 | Send: From: eServeDev@unisys.com
    INFO | wrapper | 2008/08/21 15:14:19 | Send: To: mark.vincent@unisys.com
    INFO | wrapper | 2008/08/21 15:14:19 | Send: Subject: [GBHB-VINCENTME:eServeAlertEmail:jvm_start] eServe Windows Java Service Event Notification
    INFO | wrapper | 2008/08/21 15:14:19 | Send: Date: Fri, 13 Apr 2007 03:02:00 +0900
    INFO | wrapper | 2008/08/21 15:14:19 | Send: X-Mailer: Java Service Wrapper Professional 3.3.0
    INFO | wrapper | 2008/08/21 15:14:19 | Send:
    INFO | wrapper | 2008/08/21 15:14:19 | Send: The wrapper JVM was started.\n\nPlease check on its status.\n
    INFO | wrapper | 2008/08/21 15:14:19 | Send: .
    STATUS | wrapper | 2008/08/21 15:14:20 | eServe Alert Email started.
    INFO | jvm 1 | 2008/08/21 15:14:20 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 15:14:20 | WrapperManager Debug: Send a packet PING : ping
    INFO | jvm 1 | 2008/08/21 15:14:22 | Email Message sent from eServeDev@unisys.com to markvin@btinternet.com. mark.vincent@gb.unisys.com.
    INFO | jvm 1 | 2008/08/21 15:14:24 | WrapperManager Debug: Received a packet PING : ping
    INFO | jvm 1 | 2008/08/21 15:14:24 | WrapperManager Debug: Send a packet PING : ping
    STATUS | wrapper | 2008/08/21 15:14:25 | Stopping the eServe Alert Email service...
    INFO | jvm 1 | 2008/08/21 15:14:26 | WrapperManager Debug: Received a packet SERVICE_CONTROL_CODE : 1
    INFO | jvm 1 | 2008/08/21 15:14:26 | WrapperManager Debug: ServiceControlCode from Wrapper with code 1
    INFO | wrapper | 2008/08/21 15:14:30 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:14:35 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:14:40 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:14:45 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:14:50 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:14:55 | Waiting to stop...
    INFO | jvm 1 | 2008/08/21 15:14:56 | WrapperManager Debug: Read Timed out. (Last Ping was 31800 milliseconds ago)
    INFO | jvm 1 | 2008/08/21 15:14:56 | WrapperManager: The Wrapper code did not ping the JVM for 31 seconds. Quit and let the Wrapper resynch.
    INFO | jvm 1 | 2008/08/21 15:14:56 | WrapperManager Debug: Send a packet RESTART : restart
    STATUS | wrapper | 2008/08/21 15:14:56 | JVM requested a restart.
    INFO | jvm 1 | 2008/08/21 15:14:57 | WrapperManager Debug: Thread, Wrapper-Connection, handling the shutdown process.
    INFO | jvm 1 | 2008/08/21 15:14:57 | WrapperManager Debug: calling listener.stop()
    INFO | jvm 1 | 2008/08/21 15:14:57 | WrapperManager Debug: Waiting for WrapperListener.stop runner thread to complete.
    INFO | jvm 1 | 2008/08/21 15:14:57 | WrapperManager Debug: WrapperListener.stop runner thread started.
    INFO | jvm 1 | 2008/08/21 15:14:57 | eServe Alert Email Windows Service being Stopped
    INFO | wrapper | 2008/08/21 15:15:00 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:05 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:10 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:16 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:21 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:26 | Waiting to stop...
    INFO | jvm 1 | 2008/08/21 15:15:29 | Email Message sent from eServeDev@unisys.com to markvin@btinternet.com. mark.vincent@gb.unisys.com.
    INFO | jvm 1 | 2008/08/21 15:15:29 | WrapperManager Debug: WrapperListener.stop runner thread stopped.
    INFO | jvm 1 | 2008/08/21 15:15:29 | WrapperManager Debug: returned from listener.stop() -> 1
    INFO | jvm 1 | 2008/08/21 15:15:29 | WrapperManager Debug: shutdownJVM(1) Thread:Wrapper-Connection
    INFO | jvm 1 | 2008/08/21 15:15:29 | WrapperManager Debug: Send a packet STOPPED : 1
    INFO | wrapper | 2008/08/21 15:15:31 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:15:36 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:16 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:21 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:26 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:31 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:36 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:38 | Recv:
    ERROR | wrapper | 2008/08/21 15:29:38 | Unable to send mail for jvm_start event: Unexpected SMTP code from server:
    INFO | wrapper | 2008/08/21 15:29:38 | Opening connection to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 15:29:38 | jvm_stop event mail: Connected to mailrelay.ea.unisys.com:25.
    INFO | wrapper | 2008/08/21 15:29:39 | Recv: 220 ih85.ea.unisys.com ESMTP Sendmail 8.12.11/8.12.11; Thu, 21 Aug 2008 14:29:39 GMT
    INFO | wrapper | 2008/08/21 15:29:39 | Send: HELO localhost
    INFO | wrapper | 2008/08/21 15:29:40 | Recv: 250 ih85.ea.unisys.com Hello [172.23.4.81], pleased to meet you
    INFO | wrapper | 2008/08/21 15:29:40 | Send: MAIL FROM: <eServeDev@unisys.com>
    INFO | wrapper | 2008/08/21 15:29:40 | Recv: 250 2.1.0 <eServeDev@unisys.com>... Sender ok
    INFO | wrapper | 2008/08/21 15:29:40 | Send: RCPT TO: <mark.vincent@unisys.com>
    INFO | wrapper | 2008/08/21 15:29:41 | Recv: 250 2.1.5 <mark.vincent@unisys.com>... Recipient ok
    INFO | wrapper | 2008/08/21 15:29:41 | Send: DATA
    INFO | wrapper | 2008/08/21 15:29:41 | Recv: 354 Please start mail input.
    INFO | wrapper | 2008/08/21 15:29:41 | Send: From: eServeDev@unisys.com
    INFO | wrapper | 2008/08/21 15:29:41 | Send: To: mark.vincent@unisys.com
    INFO | wrapper | 2008/08/21 15:29:41 | Send: Subject: [GBHB-VINCENTME:eServeAlertEmail:jvm_stop] eServe Windows Java Service Event Notification
    INFO | wrapper | 2008/08/21 15:29:41 | Send: Date: Fri, 13 Apr 2007 03:02:00 +0900
    INFO | wrapper | 2008/08/21 15:29:41 | Send: X-Mailer: Java Service Wrapper Professional 3.3.0
    INFO | wrapper | 2008/08/21 15:29:41 | Send:
    INFO | wrapper | 2008/08/21 15:29:41 | Send: The wrapper JVM was stopped.\n\nPlease check on its status.\n
    INFO | wrapper | 2008/08/21 15:29:41 | Send: .
    INFO | wrapper | 2008/08/21 15:29:41 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:46 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:29:51 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:32:51 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:32:56 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:33:01 | Waiting to stop...
    INFO | wrapper | 2008/08/21 15:33:06 | Waiting to stop...
    ERROR | wrapper | 2008/08/21 15:38:55 | The eServe Alert Email service is already running with status: STOP_PENDING
    INFO | wrapper | 2008/08/21 15:44:59 | Recv:
    ERROR | wrapper | 2008/08/21 15:44:59 | Unable to send mail for jvm_stop event: Unexpected SMTP code from server:
    STATUS | wrapper | 2008/08/21 15:44:59 | <-- Wrapper Stopped

    I hope this helps.
    Thanks,
    Mark.

     

  • Leif Mortenson

    Leif Mortenson - 2008-12-22

    Mark,
    This has been fixed for the 3.3.2 release. There was a problem with the way line feeds were being encoded in the data section of the email. This was causing the server to become confused about when the end of the email was found, it was thus waiting longer than the Wrapper was expecting it to.

    Cheers,
    Leif

     

  • Leif Mortenson

    Leif Mortenson - 2008-12-22
    • status: open-accepted --> closed-fixed
     

Log in to post a comment.