AnsweredAssumed Answered

Compatibility issues with Server 10.5+ & Python Windows Services (pywin32)

Question asked by pfoppe@blm.gov_BLM_EGIS on Nov 26, 2018
Latest reply on Dec 3, 2018 by pfoppe@blm.gov_BLM_EGIS

Our organization has built a few python based windows services to complete some automated tasks; these windows services are installed on the same server running ArcGIS Server so they can use the underlying python deployment and tie into arcpy.  These windows services have functioned along side ArcGIS Server quite well until the v10.5 release.  At the 10.5 release, we are starting to experience issues.  Primarily that...

 

if the python based windows service is started before the ArcGIS Server service, then all the ArcSOC.exe's fail on launch.  We can see the ArcSOC.exe briefly show up taskmgr but they disappear and throw the following exception in the ArcGIS Server manager logs - 

 

 

LevelTimeMessageSourceMachineCodeTime ElapsedUser NameProcessThreadMethod Name
DEBUGNov 26, 2018, 5:25:38 PMCleaning up previous service instance and server context.System/PublishingTools.GPServer<SERVER>.<DOMAIN>9999351278
DEBUGNov 26, 2018, 5:25:38 PMcom.esri.arcgis.discovery.servicelib.AGSException: activation failed; nested exception is: java.rmi.activation.ActivationException: object activation failed after 2 tries; nested exception is: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connect at com.esri.arcgis.discovery.servicelib.ServerContextFactory.createContext(ServerContextFactory.java:198) at com.esri.arcgis.discovery.ejb.util.EJBBase.initService(EJBBase.java:425) at com.esri.arcgis.discovery.ejb.util.EJBBase.init(EJBBase.java:277) at com.esri.arcgis.discovery.ejb.impl.GPServerSyncBean.init(GPServerSyncBean.java:47) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.openejb.core.interceptor.ReflectionInvocationContext$Invocation.invoke(ReflectionInvocationContext.java:162) at org.apache.openejb.core.interceptor.ReflectionInvocationContext$LifecycleInvocation.invoke(ReflectionInvocationContext.java:194) at org.apache.openejb.core.interceptor.ReflectionInvocationContext.proceed(ReflectionInvocationContext.java:144) at org.apache.openejb.monitoring.StatsInterceptor.record(StatsInterceptor.java:164) at org.apache.openejb.monitoring.StatsInterceptor.PostConstruct(StatsInterceptor.java:101) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.openejb.core.interceptor.ReflectionInvocationContext$Invocation.invoke(ReflectionInvocationContext.java:162) at org.apache.openejb.core.interceptor.ReflectionInvocationContext.proceed(ReflectionInvocationContext.java:144) at org.apache.openejb.core.interceptor.InterceptorStack.invoke(InterceptorStack.java:122) at org.apache.openejb.core.stateless.StatelessInstanceManager.ceateInstance(StatelessInstanceManager.java:237) at org.apache.openejb.core.stateless.StatelessInstanceManager.createInstance(StatelessInstanceManager.java:448) at org.apache.openejb.core.stateless.StatelessInstanceManager.access$100(StatelessInstanceManager.java:72) at org.apache.openejb.core.stateless.StatelessInstanceManager$BackgroundThread.run(StatelessInstanceManager.java:507) Caused by: java.rmi.activation.ActivateFailedException: activation failed; nested exception is: java.rmi.activation.ActivationException: object activation failed after 2 tries; nested exception is: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connect at sun.rmi.server.ActivatableRef.activate(ActivatableRef.java:304) at sun.rmi.server.ActivatableRef.invoke(ActivatableRef.java:133) at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:227) at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:179) at com.sun.proxy.$Proxy42.setProductCode(Unknown Source) at com.esri.arcgis.discovery.servicelib.ServerContextFactory.a(ServerContextFactory.java:255) at com.esri.arcgis.discovery.servicelib.ServerContextFactory.createContext(ServerContextFactory.java:195) ... 23 more Caused by: java.rmi.activation.ActivationException: object activation failed after 2 tries; nested exception is: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connect at sun.rmi.server.Activation$GroupEntry.activate(Activation.java:1184) at sun.rmi.server.Activation$ActivatorImpl.activate(Activation.java:406) at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:346) at sun.rmi.transport.Transport$1.run(Transport.java:200) at sun.rmi.transport.Transport$1.run(Transport.java:197) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:196) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:276) at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:253) at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:162) at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:227) at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:179) at com.sun.proxy.$Proxy41.activate(Unknown Source) at java.rmi.activation.ActivationID.activate(ActivationID.java:118) at sun.rmi.server.ActivatableRef.activate(ActivatableRef.java:277) ... 29 more Caused by: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connect at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:619) at sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:216) at sun.rmi.transport.tcp.TCPChannel.newConnection(TCPChannel.java:202) at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:130) at java.rmi.activation.ActivationGroup_Stub.newInstance(Unknown Source) at sun.rmi.server.Activation$ObjectEntry.activate(Activation.java:1455) at sun.rmi.server.Activation$GroupEntry.activate(Activation.java:1141) at sun.rmi.server.Activation$ActivatorImpl.activate(Activation.java:406) at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:346) at sun.rmi.transport.Transport$1.run(Transport.java:200) at sun.rmi.transport.Transport$1.run(Transport.java:197) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:196) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: java.net.ConnectException: Connection refused: connect at java.net.DualStackPlainSocketImpl.connect0(Native Method) at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:79) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:589) at java.net.Socket.connect(Socket.java:538) at java.net.Socket.<init>(Socket.java:434) at java.net.Socket.<init>(Socket.java:211) at sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(RMIDirectSocketFactory.java:40) at sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(RMIMasterSocketFactory.java:148) at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:613) ... 23 moreSystem/PublishingToolsEx.GPServer<SERVER>.<DOMAIN>9999351283
DEBUGNov 26, 2018, 5:25:38 PMCould not initialize service 'System.PublishingToolsEx.GPServer'. activation failed; nested exception is: java.rmi.activation.ActivationException: object activation failed after 2 tries; nested exception is: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connectSystem/PublishingToolsEx.GPServer<SERVER>.<DOMAIN>8275351283
SEVERENov 26, 2018, 5:25:38 PMCould not initialize service 'System.PublishingToolsEx.GPServer'.System/PublishingToolsEx.GPServer<SERVER>.<DOMAIN>8275351283

Here is a quick shell/example of a python based windows service that we have built: 

logging_level = "DEBUG"
logfile = r'C:\tmp\A-arcpy-pysvc-test.log'
check_interval = 30


#standard imports
import sys
import os
import logging
from logging import handlers
import traceback
import socket

import win32serviceutil
import win32service
import win32event
import servicemanager

exception_throw=False

try:
    import arcpy
except:
    sys.path.append(r'C:\Program Files\ArcGIS\Server\arcpy')
    sys.path.append(r'C:\Program Files\ArcGIS\Server\bin')
    sys.path.append(r'C:\Program Files\ArcGIS\Server\ArcToolbox\Scripts')
    import arcpy
    exception_throw = True


####################################
###     Classes/Functions     ###
####################################

class WinNtSvc (win32serviceutil.ServiceFramework):
    _svc_name_ = "A-arcpy-pysvc-test"
    _svc_display_name_ = "A Python ArcPY Service Test"

    def __init__(self,args):
        win32serviceutil.ServiceFramework.__init__(self,args)
        self.hWaitStop = win32event.CreateEvent(None,0,0,None)

    def SvcStop(self):
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        win32event.SetEvent(self.hWaitStop)
        logging.info("***** STOPPING WINDOWS NT SERVICE ON HOST '%s' *****"%socket.gethostname())

    def SvcDoRun(self):
        servicemanager.LogMsg(
            servicemanager.EVENTLOG_INFORMATION_TYPE,
                servicemanager.PYS_SERVICE_STARTED,
                (self._svc_name_,'')
        )
        self.main()


    def main(self):
        ############################
        ###     SETUP         ###
        ############################

        ###    SETUP LOGGING ###
        logging_levels={'DEBUG':logging.DEBUG,
                        'INFO':logging.INFO,
                        'WARNING':logging.WARNING,
                        'ERROR':logging.ERROR,
                        'CRITICAL':logging.CRITICAL
                        }
        lu_log_level=logging_levels[logging_level] if logging_levels.has_key(logging_level) else "WARNING"
        print "logging to %s"%logfile

        # logging.basicConfig(format='[%(asctime)s][%(levelname)s] %(message)s', datefmt='%Y/%m/%d %H:%M:%S', level=lu_log_level, filename=logfile, filemode="a")
        # 1 MB = 1048576 bytes
        logger = logging.getLogger()
        logger.setLevel(lu_log_level)
        filehandler = logging.handlers.RotatingFileHandler(logfile)
        formatter=logging.Formatter('[%(asctime)s][%(levelname)s][%(name)s][%(lineno)d] %(message)s', datefmt='%Y/%m/%d %H:%M:%S')
        filehandler.setFormatter(formatter)

        # write to file handler and standard out
        logging.getLogger().addHandler(filehandler)
        logging.getLogger().addHandler(logging.StreamHandler())


        logging.info("***** STARTING '{}' LOOP ON HOST '{}' *****".format(self._svc_name_,socket.gethostname()))
        if not logging_levels.has_key(logging_level):
            logging.warning("Failed to determine logging level.  Defaulted to 'WARNING'  Options are: %s"%",".join(logging_levels.keys()))


        ############################
        ###     PRE-LOOP CODE     ###
        ############################


        ############################
        ###     LOOPING ROUTINE     ###
        ############################
        logging.info("arcpy loaded from {}".format(arcpy))
        if exception_throw:
            logging.warning("unable to load arcpy without adjusting sys.path to: ")
            for p in sys.path:
                logging.warning("  - {}".format(p))
        logging.info("starting check every %s seconds"%check_interval)
        rc=None
        while rc != win32event.WAIT_OBJECT_0:

            logging.info("Loop")
            logging.info("Next check in %s seconds"%check_interval)
            rc = win32event.WaitForSingleObject(self.hWaitStop, check_interval*1000)


##provides an interface to register the service. You can register the service with the system by running
#python <service>.py install
##one line of executable code
if __name__ == '__main__':
    win32serviceutil.HandleCommandLine(WinNtSvc)

 

To install that service, save it as a file (ex: win_svc_sample.py), install the 64-bit version of pywin32 for python 2.7 and run this command from the windows command line as administrator: 

python.exe win_svc_sample.py install

We've tried a variety of things to resolve including: 

  1. Installing a virtual environment with the pywin32 modules and creating the service from the virtualenv
  2. Installing ArcGIS Desktop along side server
  3. Tested on both 10.4.1, 10.5.1, and 10.6.1 on windows 2008 and 2012.  

 

We can run a windows service just fine as long as we do not import arcpy.  If we import arcpy then the ArcSOC.exe fail to launch.  We were able to achieve success by installing ArcGIS Desktop along side the server, and can confirm that if arcpy is loaded from <module 'arcpy' from 'C:\Program Files (x86)\ArcGIS\Desktop10.6\ArcPy\arcpy\__init__.pyc'>

then it will function when co-located on the same server as ArcGIS Server.  However, if desktop is not there, then arcpy is loaded from <module 'arcpy' from '<C:\Program Files\ArcGIS\Server\ArcPy\arcpy\__init__.pyc>'then the ArcSOC.exe's fail.  

 

Thoughts from the community? 

Is anyone else running python based windows services on the same server as ArcGIS for Server? 

Any idea why importing arcpy from a windows service would prevent arcgis server from functioning?

 

We can move these windows services to a new host running ArcGIS Desktop with background geoprocessing in the short term, however we have larger plans to co-locate with server at multiple locations in the future and would really like to ensure compatibility with server.  The error

java.rmi.activation.ActivationException: object activation failed after 2 tries; nested exception is: java.rmi.ConnectException: Connection refused to host: <XX.XXX.XX.XX>; nested exception is: java.net.ConnectException: Connection refused: connect

 

Suggests a firewall block (all are disabled and this works without the python based windows service) or a different component is failing which is listening for an active connection.  

 

Interesting enough.. if the server is started first, then the python windows service, everything appears to work as expected.  Including stopping/re-starting arcgis server services (the ArcSOC.exe do not fail to launch as long as the server is running correctly). 

 

Thanks for any help/advise.  

Outcomes