servicemanager LogInfoMsg and LogErrorMsg are crashing

[zapdaniels]

First of all, thank you for the great library and the effort you put in!

I'm using

Python 3.12.0 (tags/v3.12.0:0fb18b0, Oct  2 2023, 13:03:39) [MSC v.1935 64 bit (AMD64)] on win32
pywin32==306

I ran into an issue after updating a Windows background service from Py3.11 to Py3.12

Using the servicemanager.LogInfoMsg function in Python 3.12 may result in a C-level crash, and it cannot be caught as an exception. No log visible in the Windows Event Viewer.

> py -3.12 -c "import servicemanager;servicemanager.LogInfoMsg('Test');print('ok')"

The same sequence of commands with Python 3.11 works properly.
Log is visible in Windows Event Viewer.

> py -3.11 -c "import servicemanager;servicemanager.LogInfoMsg('Test');print('ok')"
ok

Not sure if this data is helpful: Starting my entire application, I see such information in the Event Viewer as error.

Faulting application name: pythonservice.exe, version: 3.12.306.0, time stamp: 0x641ef01c
Faulting module name: python312.dll, version: 3.12.150.1013, time stamp: 0x651ac03d
Exception code: 0xc0000005
Fault offset: 0x000000000003809f
Faulting process id: 0x284c
Faulting application start time: 0x01da2804bd693713
Faulting application path: c:\tools\Python312\pythonservice.exe
Faulting module path: c:\tools\Python312\python312.dll
Report Id: ebca65a0-8bc8-4be5-a14f-a9f8053c9ea7

[avivbrg]

I'm seeing the same behaviour, though in my case the log is visible in the event viewer
(also tested with 3.12.1, same issue)

[DavidRueter]

I am seeing this same behavior: calling LogInfoMsg results in the message being logged to the Windows Application log as expected, but then the app crashes with no exception or error message in the console.

However, there are two log entries written to the Windows Application log:

Error 2/10/2024 8:29:48 AM Application Error 1000 (100)
Information 2/10/2024 8:29:49 AM Windows Error Reporting 1001 None

Here are the details for the Application Error:

Log Name: Application
Source: Application Error
Date: 2/10/2024 8:29:48 AM
Event ID: 1000
Task Category: (100)
Level: Error
Keywords: Classic
User: N/A
Computer: DESKTOP-Q6LAJPN
Description:
Faulting application name: python.exe, version: 3.12.2150.1013, time stamp: 0x65c2a4c7
Faulting module name: python312.dll, version: 3.12.2150.1013, time stamp: 0x65c2a47f
Exception code: 0xc0000005
Fault offset: 0x000000000000cc2f
Faulting process id: 0x2abc
Faulting application start time: 0x01da5c3e58fc9c62
Faulting application path: C:\Prog\Python312\python.exe
Faulting module path: C:\Prog\Python312\python312.dll
Report Id: df055ae1-a7e3-45fb-b3e7-fae084950909
Faulting package full name:
Faulting package-relative application ID:
Event Xml:



1000
0
2
100
0
0x80000000000000

1472684


Application
DESKTOP-Q6LAJPN



python.exe
3.12.2150.1013
65c2a4c7
python312.dll
3.12.2150.1013
65c2a47f
c0000005
000000000000cc2f
2abc
01da5c3e58fc9c62
C:\Prog\Python312\python.exe
C:\Prog\Python312\python312.dll
df055ae1-a7e3-45fb-b3e7-fae084950909

And here are the details from the Windows Error Reporting entry:

Log Name: Application
Source: Windows Error Reporting
Date: 2/10/2024 8:29:49 AM
Event ID: 1001
Task Category: None
Level: Information
Keywords: Classic
User: N/A
Computer: DESKTOP-Q6LAJPN
Description:
Fault bucket 1783893696342404100, type 4
Event Name: APPCRASH
Response: Not available
Cab Id: 0

Problem signature:
P1: python.exe
P2: 3.12.2150.1013
P3: 65c2a4c7
P4: python312.dll
P5: 3.12.2150.1013
P6: 65c2a47f
P7: c0000005
P8: 000000000000cc2f
P9:
P10:

Attached files:
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC507.tmp.dmp
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC576.tmp.WERInternalMetadata.xml
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC596.tmp.xml
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC594.tmp.csv
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC5B4.tmp.txt

These files may be available here:
\?\C:\ProgramData\Microsoft\Windows\WER\ReportArchive\AppCrash_python.exe_6ebd91751fd94fbf36a912f32d23fdffcea4a_f0ccd126_f7d84986-3355-41b7-a080-67958eda60e2

Analysis symbol:
Rechecking for solution: 0
Report Id: df055ae1-a7e3-45fb-b3e7-fae084950909
Report Status: 268435456
Hashed bucket: 574307885d08226488c1a9dd878c2c04
Cab Guid: 0
Event Xml:



1001
0
4
0
0
0x80000000000000

1472685


Application
DESKTOP-Q6LAJPN



1783893696342404100
4
APPCRASH
Not available
0
python.exe
3.12.2150.1013
65c2a4c7
python312.dll
3.12.2150.1013
65c2a47f
c0000005
000000000000cc2f





\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC507.tmp.dmp
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC576.tmp.WERInternalMetadata.xml
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC596.tmp.xml
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC594.tmp.csv
\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERC5B4.tmp.txt
\?\C:\ProgramData\Microsoft\Windows\WER\ReportArchive\AppCrash_python.exe_6ebd91751fd94fbf36a912f32d23fdffcea4a_f0ccd126_f7d84986-3355-41b7-a080-67958eda60e2


0
df055ae1-a7e3-45fb-b3e7-fae084950909
268435456
574307885d08226488c1a9dd878c2c04
0

[ElliotGarbus]

I'm experiencing the same issue with python 3.12.1

Here is the code I'm using:

# Code is lifted from this blog post:
# https://metallapan.se/post/windows-service-pywin32-pyinstaller/

import sys
import time

import servicemanager  # Simple setup and logging
import win32service  # Events
import win32serviceutil  # ServiceFramework and commandline helper


# sys.path.insert(0, "..")
# from mylibrary import ProprietaryClass
# from mylibrary.subdir import MyLib_Constants


class MyService:
    """Silly little application stub"""

    def stop(self):
        """Stop the service"""
        self.running = False

    def run(self):
        """Main service loop. This is where work is done!"""
        self.running = True
        # secret = ProprietaryClass()
        while self.running:
            time.sleep(10)  # Important work
            # secret_result = secret.hello_world()
            servicemanager.LogInfoMsg(f"{secret_result} {MyLib_Constants}")


class MyServiceFramework(win32serviceutil.ServiceFramework):
    _svc_name_ = 'MyService'
    _svc_display_name_ = 'My Service display name'

    def SvcStop(self):
        """Stop the service"""
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        self.service_impl.stop()
        self.ReportServiceStatus(win32service.SERVICE_STOPPED)

    def SvcDoRun(self):
        """Start the service; does not return until stopped"""
        self.ReportServiceStatus(win32service.SERVICE_START_PENDING)
        self.service_impl = MyService()
        self.ReportServiceStatus(win32service.SERVICE_RUNNING)
        # Run the service
        self.service_impl.run()


def init():
    if len(sys.argv) == 1:
        servicemanager.Initialize()
        servicemanager.PrepareToHostSingle(MyServiceFramework)
        servicemanager.StartServiceCtrlDispatcher()
    else:
        win32serviceutil.HandleCommandLine(MyServiceFramework)


if __name__ == '__main__':
    init()

[maccamb]

I am experiencing the same issue. Is this the correct forum to post on?

If it is then attached inline are the contents of the associated Report.wer file:

Version=1
EventType=APPCRASH
EventTime=133575902720464133
ReportType=2
Consent=1
UploadTime=133575902725050996
ReportStatus=268435456
ReportIdentifier=823493c6-5512-4b81-86a2-acfde51244ee
IntegratorReportIdentifier=4598584a-fd33-4262-89ae-0e50fc817d5b
Wow64Host=34404
NsAppName=test.exe
AppSessionGuid=0000179c-0000-0009-95e6-c361938eda01
TargetAppId=W:00061dd68bdd826965f6c90daa8b7ff486660000ffff!0000ba8b2a53d175b81101916c75210fb20beb28423c!test.exe
TargetAppVer=2024//04//14:17:42:06!7543d8!test.exe
BootId=4294967295
TargetAsId=583
IsFatal=1
EtwNonCollectReason=1
Response.BucketId=9fa208ac7d6291b25d2a8a0a7614126c
Response.BucketTable=4
Response.LegacyBucketId=2101643953657090668
Response.type=4
Sig[0].Name=Application Name
Sig[0].Value=test.exe
Sig[1].Name=Application Version
Sig[1].Value=0.0.0.0
Sig[2].Name=Application Timestamp
Sig[2].Value=661c156e
Sig[3].Name=Fault Module Name
Sig[3].Value=python312.dll
Sig[4].Name=Fault Module Version
Sig[4].Value=3.12.2150.1013
Sig[5].Name=Fault Module Timestamp
Sig[5].Value=65c2a47f
Sig[6].Name=Exception Code
Sig[6].Value=c0000005
Sig[7].Name=Exception Offset
Sig[7].Value=000000000000cc2f
DynamicSig[1].Name=OS Version
DynamicSig[1].Value=10.0.22631.2.0.0.256.48
DynamicSig[2].Name=Locale ID
DynamicSig[2].Value=1033
DynamicSig[22].Name=Additional Information 1
DynamicSig[22].Value=fa6f
DynamicSig[23].Name=Additional Information 2
DynamicSig[23].Value=fa6fb7dd40186b4810d26d1ca09a7044
DynamicSig[24].Name=Additional Information 3
DynamicSig[24].Value=a877
DynamicSig[25].Name=Additional Information 4
DynamicSig[25].Value=a87723ca5a16692a5a5ebf3576a4ef47
UI[2]=C:\Users\akbha\Desktop\test.exe
UI[5]=Close
UI[8]=test.exe stopped working and was closed
UI[9]=A problem caused the application to stop working correctly. Windows will notify you if a solution is available.
UI[10]=&Close
LoadedModule[0]=C:\Users\akbha\Desktop\test.exe
LoadedModule[1]=C:\Windows\SYSTEM32\ntdll.dll
LoadedModule[2]=C:\Windows\System32\KERNEL32.DLL
LoadedModule[3]=C:\Windows\System32\KERNELBASE.dll
LoadedModule[4]=C:\Windows\System32\USER32.dll
LoadedModule[5]=C:\Windows\System32\win32u.dll
LoadedModule[6]=C:\Windows\System32\GDI32.dll
LoadedModule[7]=C:\Windows\System32\gdi32full.dll
LoadedModule[8]=C:\Windows\System32\msvcp_win.dll
LoadedModule[9]=C:\Windows\System32\ucrtbase.dll
LoadedModule[10]=C:\Windows\System32\ADVAPI32.dll
LoadedModule[11]=C:\Windows\System32\msvcrt.dll
LoadedModule[12]=C:\Windows\System32\sechost.dll
LoadedModule[13]=C:\Windows\System32\bcrypt.dll
LoadedModule[14]=C:\Windows\System32\RPCRT4.dll
LoadedModule[15]=C:\Windows\system32\_MEI27562\python312.dll
LoadedModule[16]=C:\Windows\System32\WS2_32.dll
LoadedModule[17]=C:\Windows\SYSTEM32\VERSION.dll
LoadedModule[18]=C:\Windows\system32\_MEI27562\VCRUNTIME140.dll
LoadedModule[19]=C:\Windows\System32\bcryptprimitives.dll
LoadedModule[20]=C:\Windows\system32\_MEI27562\pywin32_system32\pywintypes312.dll
LoadedModule[21]=C:\Windows\System32\ole32.dll
LoadedModule[22]=C:\Windows\System32\combase.dll
LoadedModule[23]=C:\Windows\System32\OLEAUT32.dll
LoadedModule[24]=C:\Windows\system32\_MEI27562\VCRUNTIME140_1.dll
LoadedModule[25]=C:\Windows\system32\_MEI27562\win32\win32api.pyd
LoadedModule[26]=C:\Windows\System32\SHELL32.dll
LoadedModule[27]=C:\Windows\SYSTEM32\secur32.dll
LoadedModule[28]=C:\Windows\SYSTEM32\SSPICLI.DLL
LoadedModule[29]=C:\Windows\system32\_MEI27562\win32\win32service.pyd
LoadedModule[30]=C:\Windows\system32\_MEI27562\win32\servicemanager.pyd
State[0].Key=Transport.DoneStage1
State[0].Value=1
OsInfo[0].Key=vermaj
OsInfo[0].Value=10
OsInfo[1].Key=vermin
OsInfo[1].Value=0
OsInfo[2].Key=verbld
OsInfo[2].Value=22631
OsInfo[3].Key=ubr
OsInfo[3].Value=3447
OsInfo[4].Key=versp
OsInfo[4].Value=0
OsInfo[5].Key=arch
OsInfo[5].Value=9
OsInfo[6].Key=lcid
OsInfo[6].Value=1033
OsInfo[7].Key=geoid
OsInfo[7].Value=244
OsInfo[8].Key=sku
OsInfo[8].Value=48
OsInfo[9].Key=domain
OsInfo[9].Value=0
OsInfo[10].Key=prodsuite
OsInfo[10].Value=256
OsInfo[11].Key=ntprodtype
OsInfo[11].Value=1
OsInfo[12].Key=platid
OsInfo[12].Value=10
OsInfo[13].Key=sr
OsInfo[13].Value=0
OsInfo[14].Key=tmsi
OsInfo[14].Value=222623649
OsInfo[15].Key=osinsty
OsInfo[15].Value=2
OsInfo[16].Key=iever
OsInfo[16].Value=11.1.22621.0-11.0.1000
OsInfo[17].Key=portos
OsInfo[17].Value=0
OsInfo[18].Key=ram
OsInfo[18].Value=6143
OsInfo[19].Key=svolsz
OsInfo[19].Value=63
OsInfo[20].Key=wimbt
OsInfo[20].Value=0
OsInfo[21].Key=blddt
OsInfo[21].Value=220506
OsInfo[22].Key=bldtm
OsInfo[22].Value=1250
OsInfo[23].Key=bldbrch
OsInfo[23].Value=ni_release
OsInfo[24].Key=bldchk
OsInfo[24].Value=0
OsInfo[25].Key=wpvermaj
OsInfo[25].Value=0
OsInfo[26].Key=wpvermin
OsInfo[26].Value=0
OsInfo[27].Key=wpbuildmaj
OsInfo[27].Value=0
OsInfo[28].Key=wpbuildmin
OsInfo[28].Value=0
OsInfo[29].Key=osver
OsInfo[29].Value=10.0.22621.3447.amd64fre.ni_release.220506-1250
OsInfo[30].Key=buildflightid
OsInfo[31].Key=edition
OsInfo[31].Value=Professional
OsInfo[32].Key=ring
OsInfo[32].Value=Retail
OsInfo[33].Key=expid
OsInfo[33].Value=MD:283BAEF,ME:28279A6,ME:2A69053,MD:2E3923D
OsInfo[34].Key=fconid
OsInfo[34].Value=15546617,1,2,0;19193777,0,2,0;19638787,0,2,0;23531064,2,2,0;23562335,2,2,0;23563673,2,2,0;23877894,1,2,0;32862274,0,2,1;35681102,0,1,0;36803287,0,2,1;36803295,0,2,0;36803303,0,2,0;38277973,0,1,1;38859191,0,2,0;39145991,0,2,0;39263329,1,2,0;39281392,0,2,0;40025975,0,1,0;40616880,0,1,0;40883769,0,1,0;40981503,0,1,0;41135193,0,1,1;41137130,0,1,0;41342175,0,1,0;41655236,0,2,0;41772259,0,2,0;41799415,0,2,1;42052423,0,2,0;42105254,0,2,0;42963857,0,2,1;43133808,1,2,1;43169616,0,1,0;43203978,0,2,1;43231896,0,0,0;43572857,0,2,0;43772553,0,1,0;43844371,0,1,0;43978769,0,1,1;43998261,0,2,1;44325080,0,1,0;44470355,0,2,0;44521793,0,1,0;44533041,0,0,1;44552141,0,1,0;44776738,0,2,0;45113694,0,2,1;45185354,0,2,0;45668242,0,2,1;45732051,0,2,0;45786062,0,2,1;45796396,0,2,0;45930103,0,2,0;45949789,0,2,0;45951844,0,2,0;45952583,0,2,0;45952594,0,2,0;45952795,0,2,0;45952819,0,2,0;45952823,0,2,0;45952872,0,2,0;45991456,0,1,1;45994554,0,2,0;45999439,0,2,0;46009617,0,2,1;46111200,0,2,1;46251949,0,2,1;46541070,0,2,0;46551074,0,1,1;46557400,0,1,0;46604216,0,2,1;46619189,0,2,1;46656382,0,2,1;46715659,0,0,1;46717502,0,2,0;46982417,0,2,0;46984166,0,0,0;47134595,0,1,0;47205155,0,2,1;47270778,0,2,1;47381523,0,2,1;47526873,1,2,1;47681899,0,1,1;47916854,0,1,0;47942561,0,0,1;47973375,0,1,1;47991031,0,2,1;48057519,0,2,0;48082515,0,0,0;48128028,0,2,0;48141486,0,2,0;48433541,0,1,0;48433706,0,1,0;48433719,0,1,0;48468527,0,1,0;48468541,0,1,0;48503047,0,2,1;48797432,1,2,1
OsInfo[35].Key=containerid
OsInfo[36].Key=containertype
OsInfo[37].Key=edu
OsInfo[37].Value=0
OsInfo[38].Key=servicinginprogress
OsInfo[38].Value=0
OsInfo[39].Key=featureupdatependingreboot
OsInfo[39].Value=0
FriendlyEventName=Stopped working
ConsentKey=APPCRASH
AppName=test.exe
AppPath=C:\Users\akbha\Desktop\test.exe
NsPartner=windows
NsGroup=windows8
ApplicationIdentity=5BD169AF9E639B269B164A74EB1E980B
MetadataHash=172243955

[Florian-Laport]

This is still an issue; I'm able to reproduce with Python 3.12.5 and pywin32 306.

[guentner]

I have the same issue with Python 3.13.0 and PyWin32 build 308.

I tried to analyze this, so I installed a debug build of Python 3.13.0 and compiled the latest pywin32 from source (14df895).

When running the following example:

import servicemanager
servicemanager.LogErrorMsg("hello")

Python exits with the following error message:

Fatal Python error: _PyMem_DebugFree: Python memory allocator called without holding the GIL

While calling PyWinObject_FreeWCHAR in DoLogMessage:

pywin32/win32/src/PythonService.cpp

Lines 176 to 178 in 14df895

	Py_BEGIN_ALLOW_THREADS ok = ReportError(errorCode, inserts, errorType);
	PyWinObject_FreeWCHAR(msg);
	Py_END_ALLOW_THREADS if (!ok) return PyWin_SetAPIError("RegisterEventSource/ReportEvent");

I don't know much about the Python interpreter C API, but based on the error message, I suspect that the call to PyWinObject_FreeWCHAR should be moved outside of the Py_BEGIN_ALLOW_THREADS/Py_END_ALLOW_THREADS region.

[JacobNolan1]

I've had the exact same issue having tested on both Python 3.12.2 and 3.12.7

Exact same faulting application crash in Event Viewer as @zapdaniels mentioned.

Faulting application name: pythonservice.exe, version: 3.12.308.0, time stamp: 0x670add2b
Faulting module name: python312.dll, version: 3.12.2150.1013, time stamp: 0x65c2a47f
Exception code: 0xc0000005
Fault offset: 0x000000000000cc2f
Faulting process id: 0x278
Faulting application start time: 0x01db3582f2494260
Faulting application path: C:\Program Files\Python312\pythonservice.exe
Faulting module path: C:\Program Files\Python312\python312.dll
Report Id: ab35bf3e-17f9-4e93-9fc7-11a2e6c55f1e
Faulting package full name:
Faulting package-relative application ID:

After @guentner provided info about the servicemanager crash I've since removed my calls to LogInfoMsg() and my service runs fine although without servicemanager logs.