I
IIS
Guest
W3C Logging services goes in to the Stop state unexpectedly/automatically on Windows server 2016
OBSERVATIONS:
Procmon was not giving us much information on the caller of process issuing stop command to service . So we collected SCM ETL using below steps
Start tracing:
logman create trace "base_screg" -ow -o c:\base_screg.etl -p "Service Control Manager" 0xffffffffffffffff 0xff -nb 16 16 -bs 1024 -mode Circular -f bincirc -max 4096 -ets
logman update trace "base_screg" -p "Microsoft-Windows-Services" 0xffffffffffffffff 0xff -ets
logman update trace "base_screg" -p {EBCCA1C2-AB46-4A1D-8C2A-906C2FF25F39} 0xffffffffffffffff 0xff -ets
Stop tracing:
logman stop "base_screg" -ets
TEST PERFORMED LOCALLY:
---default service state of w3logsvc = manual
--we created custom field in IIS logging for testing
--sent a request and we see w3logsvc service in "running" state and we see request getting logged in IIS logs.
--after about 30-40minutes, we see service automatically stopped as i was not sending any active request.
--checked the SCM logs to see who is the caller and see its PID PID 0x000014a0=5280.
65706 [2] 03D4.9D84::12/26/19-13:32:41.2477953 [SCM] scopen_cxx1159 ScOpenService() - ScOpenService: Service w3logsvc, handle 0x000001E4376E5100, PID 0x000014a0, access 0x00000024, refCount 4
65707 [2] 03D4.9D84::12/26/19-13:32:41.2478933 [SCM] control_cxx651 ScControlService() - ScControlService: Service w3logsvc, control 1, reason 0x00000000, comment NULL
65708 [2] 03D4.9D84::12/26/19-13:32:41.2480347 [SCM] control_cxx4422 ScSendControl() - ScSendControl: Sending control 0x00000001 to service/module w3logsvc, caller PID 0x000014a0, channel 0x000001E437857DC0, refs 0x3
65709 [0] 03D4.82EC::12/26/19-13:32:41.2481432 [SCM] status_cxx291 RSetServiceStatus() - RSetServiceStatus: Status field accepted, service w3logsvc, state 0x00000003(SERVICE_STOP_PENDING), exit 0, sexit 0, controls 0x00000000
65710 [0] 03D4.82EC::12/26/19-13:32:41.2481461 [SCM] status_cxx414 CWin32ServiceRecord::SetStatus() - Service Record updated with new status for service w3logsvc
65711 [0]03D4.82EC::12/26/19-13:32:41.2481472 [Microsoft-Windows-Services/Diagnostic] ExecutionPhase=0, CurrentState=3, StartType=3, PID=21772, ServiceName=w3logsvc, ImageName=C:\WINDOWS\system32\svchost.exe -k apphost
65712 [5] 03D4.9D84::12/26/19-13:32:41.2483634 [SCM] control_cxx4865 ScSendControl() - ScSendControl: Service w3logsvc, control 1, user S-1-5-18, caller PID 0x000014a0
65713 [5] 03D4.9D84::12/26/19-13:32:41.2483642 [SCM] control_cxx4911 ScReleaseRefAndFreeServiceChannelContextUnlocked() - ScReleaseRefAndFreeServiceChannelContextUnlocked: Channel 0x000001E437857DC0, refs 0x2
65714 [5] 03D4.9D84::12/26/19-13:32:41.2535380 [SCM] status_cxx291 RSetServiceStatus() - RSetServiceStatus: Status field accepted, service w3logsvc, state 0x00000001(SERVICE_STOPPED), exit 0, sexit 0, controls 0x00000000
65715 [5] 03D4.9D84::12/26/19-13:32:41.2536200 [SCM] status_cxx414 CWin32ServiceRecord::SetStatus() - Service Record updated with new status for service w3logsvc
65716 [5] 03D4.9D84::12/26/19-13:32:41.2537038 [SCM] scopen_cxx457 RCloseServiceHandle() - RCloseServiceHandle: Handle 0x000001E437743820, PID 0x0000550c
65717 [6]03D4.85AC::12/26/19-13:32:41.2539341 [Microsoft-Windows-Services/Diagnostic] ExecutionPhase=0, CurrentState=1, StartType=3, PID=0, ServiceName=w3logsvc, ImageName=
65718 [6] 03D4.85AC::12/26/19-13:32:41.2539370 [SCM] dataman_cxx3728 ScTerminateServiceProcess() - TerminateServiceProcess, sending Control...
So when we don’t have any active request to IIS, W3SVC service stops the W3logsvc service and runs it when the site receives a request. This service is stopped by default and set to “manual” startup. When you add a field to enhanced logging and the site receives a request, the service will be started .this is a By design behavior.
Continue reading...
OBSERVATIONS:
Procmon was not giving us much information on the caller of process issuing stop command to service . So we collected SCM ETL using below steps
Start tracing:
logman create trace "base_screg" -ow -o c:\base_screg.etl -p "Service Control Manager" 0xffffffffffffffff 0xff -nb 16 16 -bs 1024 -mode Circular -f bincirc -max 4096 -ets
logman update trace "base_screg" -p "Microsoft-Windows-Services" 0xffffffffffffffff 0xff -ets
logman update trace "base_screg" -p {EBCCA1C2-AB46-4A1D-8C2A-906C2FF25F39} 0xffffffffffffffff 0xff -ets
Stop tracing:
logman stop "base_screg" -ets
TEST PERFORMED LOCALLY:
---default service state of w3logsvc = manual
--we created custom field in IIS logging for testing
--sent a request and we see w3logsvc service in "running" state and we see request getting logged in IIS logs.
--after about 30-40minutes, we see service automatically stopped as i was not sending any active request.
--checked the SCM logs to see who is the caller and see its PID PID 0x000014a0=5280.
65706 [2] 03D4.9D84::12/26/19-13:32:41.2477953 [SCM] scopen_cxx1159 ScOpenService() - ScOpenService: Service w3logsvc, handle 0x000001E4376E5100, PID 0x000014a0, access 0x00000024, refCount 4
65707 [2] 03D4.9D84::12/26/19-13:32:41.2478933 [SCM] control_cxx651 ScControlService() - ScControlService: Service w3logsvc, control 1, reason 0x00000000, comment NULL
65708 [2] 03D4.9D84::12/26/19-13:32:41.2480347 [SCM] control_cxx4422 ScSendControl() - ScSendControl: Sending control 0x00000001 to service/module w3logsvc, caller PID 0x000014a0, channel 0x000001E437857DC0, refs 0x3
65709 [0] 03D4.82EC::12/26/19-13:32:41.2481432 [SCM] status_cxx291 RSetServiceStatus() - RSetServiceStatus: Status field accepted, service w3logsvc, state 0x00000003(SERVICE_STOP_PENDING), exit 0, sexit 0, controls 0x00000000
65710 [0] 03D4.82EC::12/26/19-13:32:41.2481461 [SCM] status_cxx414 CWin32ServiceRecord::SetStatus() - Service Record updated with new status for service w3logsvc
65711 [0]03D4.82EC::12/26/19-13:32:41.2481472 [Microsoft-Windows-Services/Diagnostic] ExecutionPhase=0, CurrentState=3, StartType=3, PID=21772, ServiceName=w3logsvc, ImageName=C:\WINDOWS\system32\svchost.exe -k apphost
65712 [5] 03D4.9D84::12/26/19-13:32:41.2483634 [SCM] control_cxx4865 ScSendControl() - ScSendControl: Service w3logsvc, control 1, user S-1-5-18, caller PID 0x000014a0
65713 [5] 03D4.9D84::12/26/19-13:32:41.2483642 [SCM] control_cxx4911 ScReleaseRefAndFreeServiceChannelContextUnlocked() - ScReleaseRefAndFreeServiceChannelContextUnlocked: Channel 0x000001E437857DC0, refs 0x2
65714 [5] 03D4.9D84::12/26/19-13:32:41.2535380 [SCM] status_cxx291 RSetServiceStatus() - RSetServiceStatus: Status field accepted, service w3logsvc, state 0x00000001(SERVICE_STOPPED), exit 0, sexit 0, controls 0x00000000
65715 [5] 03D4.9D84::12/26/19-13:32:41.2536200 [SCM] status_cxx414 CWin32ServiceRecord::SetStatus() - Service Record updated with new status for service w3logsvc
65716 [5] 03D4.9D84::12/26/19-13:32:41.2537038 [SCM] scopen_cxx457 RCloseServiceHandle() - RCloseServiceHandle: Handle 0x000001E437743820, PID 0x0000550c
65717 [6]03D4.85AC::12/26/19-13:32:41.2539341 [Microsoft-Windows-Services/Diagnostic] ExecutionPhase=0, CurrentState=1, StartType=3, PID=0, ServiceName=w3logsvc, ImageName=
65718 [6] 03D4.85AC::12/26/19-13:32:41.2539370 [SCM] dataman_cxx3728 ScTerminateServiceProcess() - TerminateServiceProcess, sending Control...
So when we don’t have any active request to IIS, W3SVC service stops the W3logsvc service and runs it when the site receives a request. This service is stopped by default and set to “manual” startup. When you add a field to enhanced logging and the site receives a request, the service will be started .this is a By design behavior.
Continue reading...