Jump to content

emby server not shutting down

revengineer

By revengineer
in General/Windows

 Share

Recommended Posts

revengineer

revengineer   127

Posted
Posted

I have commented in several threads that the emby server service does not shut down on my Windows Server 2012 so that every update, including those for plugins, require a server reboot. I did some debugging following the blog post https://blogs.technet.microsoft.com/markrussinovich/2005/08/17/unkillable-processes/. The output is shown below and points to the driver AFD.SYS being at fault. This is a windows driver, and there is nothing I can do about that. I already updated my network card driver as suggested elsewhere online.

 

Not sure if this helps in any way, but I thought I report it in case this gets taken seriously at some point.

C:\Program Files (x86)\LiveKD>livekd64

LiveKd v5.62 - Execute kd/windbg on a live system
Sysinternals - www.sysinternals.com
Copyright (C) 2000-2016 Mark Russinovich and Ken Johnson

Launching C:\Program Files (x86)\Windows Kits\8.0\Debuggers\x64\kd.exe:

Microsoft (R) Windows Debugger Version 6.2.9200.20512 AMD64
Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [C:\Windows\livekd.dmp]
Kernel Complete Dump File: Full address space is available

Comment: 'LiveKD live system view'
Symbol search path is: srv*c:\Symbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
Windows 8 Kernel Version 9200 MP (4 procs) Free x64
Product: LanManNt, suite: SmallBusiness TerminalServer SmallBusinessRestricted SingleUserTS
Built by: 9200.22227.amd64fre.win8_ldr.170705-2007
Machine Name:
Kernel base = 0xfffff803`edc6d000 PsLoadedModuleList = 0xfffff803`edf34a00
Debug session time: Thu Aug 10 15:36:36.903 2017 (UTC - 4:00)
System Uptime: 1 days 11:54:10.687
Loading Kernel Symbols
...............................................................
................................................................
.........................
Loading User Symbols

Loading unloaded module list
.....................
0: kd> !process 0 7 MediaBrowser.ServerApplication.exe
*** ERROR: Module load completed but symbols could not be loaded for LiveKdD.SYS
PROCESS fffffa8012c76980
    SessionId: 0  Cid: 22d0    Peb: 7f5ffb1e000  ParentCid: 02c0
    DirBase: 1c54ea000  ObjectTable: fffff8a000af6880  HandleCount: <Data Not Accessible>
    Image: MediaBrowser.ServerApplication.exe
    VadRoot fffffa8011e28c00 Vads 634 Clone 0 Private 136706. Modified 2899730. Locked 1892.
    DeviceMap fffff8a009abc3a0
    Token                             fffff8a009bda060
    ElapsedTime                       1 Day 11:48:02.068
    UserTime                          00:05:11.234
    KernelTime                        00:00:17.437
    QuotaPoolUsage[PagedPool]         753920
    QuotaPoolUsage[NonPagedPool]      652488
    Working Set Sizes (now,min,max)  (153377, 50, 345) (613508KB, 200KB, 1380KB)
    PeakWorkingSetSize                204177
    VirtualSize                       18139 Mb
    PeakVirtualSize                   18147 Mb
    PageFaultCount                    2299067
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      190917

        THREAD fffffa8013078080  Cid 22d0.044c  Teb: 000007f5ffb1c000 Win32Thread: fffff901006e4b80 WAIT: (Executive) Ke
rnelMode Non-Alertable
            fffff88018088860  NotificationEvent
        IRP List:
            fffffa80124b08b0: (0006,01f0) Flags: 00000404  Mdl: 00000000
        Not impersonating
        DeviceMap                 fffff8a009abc3a0
        Owning Process            fffffa8012c76980       Image:         MediaBrowser.ServerApplication.exe
        Attached Process          N/A            Image:         N/A
        Wait Start TickCount      8183220        Ticks: 88824 (0:00:23:07.875)
        Context Switch Count      1958           IdealProcessor: 1
        UserTime                  00:00:04.687
        KernelTime                00:00:00.437
        Win32 Start Address 0x000000b6743ed89e
        Stack Init fffff88018088c90 Current fffff880180884e0
        Base fffff88018089000 Limit fffff88018083000 Call 0
        Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
        Child-SP          RetAddr           : Args to Child                                                           :
Call Site
        fffff880`18088520 fffff803`edd0e429 : fffffa80`13078080 00000000`00000000 fffff803`ee08fee8 00000000`00000000 :
nt!KiSwapContext+0x76
        fffff880`18088660 fffff803`edd0c26f : 0001220c`00000001 fffffa80`13fd4010 00000000`00000000 00000000`00000000 :
nt!KiCommitThreadWait+0x229
        fffff880`180886d0 fffff880`04044b50 : fffff880`18088860 00000000`00000000 fffff880`18088800 fffff880`18088700 :
nt!KeWaitForSingleObject+0x1cf
        fffff880`18088760 fffff880`04044284 : 00000000`00000c6c 00000000`00000000 fffffa80`124b08b0 fffffa80`13003480 :
afd!AfdCleanupCore+0x400
        fffff880`180888c0 fffff803`ee0d1056 : fffffa80`12bee6f0 00000000`00000000 00000000`00000000 fffffa80`12fba940 :
afd!AfdDispatch+0x54
        fffff880`18088920 fffff803`ee0b607a : fffffa80`12fba910 00000000`00000000 fffffa80`12fba930 00000000`00000000 :
nt!IopCloseFile+0x146
        fffff880`180889b0 fffff803`ee0b62b6 : fffff8a0`00af6880 fffff8a0`00af6900 00000000`00000c6c 00000000`0bac4180 :
nt!ObpDecrementHandleCount+0x9a
        fffff880`18088a50 fffff803`edce4c53 : 00000000`00000001 fffffa80`13078080 fffff880`18088b80 000000ba`c3e68300 :
nt!NtClose+0x206
        fffff880`18088b00 000007f8`2bb2355a : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 :
nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880`18088b00)
        000000b6`7452e058 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 :
0x000007f8`2bb2355a


0: kd> !irp fffffa80124b08b0
Irp is active with 4 stacks 4 is current (= 0xfffffa80124b0a58)
 No Mdl: No System Buffer: Thread fffffa8013078080:  Irp stack trace.
     cmd  flg cl Device   File     Completion-Context
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

                        Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

                        Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

                        Args: 00000000 00000000 00000000 00000000
>[ 12, 0]   0  0 fffffa800dab3420 fffffa8012bee6f0 00000000-00000000
               \Driver\AFD
                        Args: 00000000 00000000 00000000 00000000
0: kd>
Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted (edited)

Luke: Log is attached here (and I probably posted somewhere before). The last log entry is always "Disposing DnlaEntrypoint". This is also the case in the log bfir3 linked. For what its worth, I recently disabled all DNLA and it did not change this behavior. Maybe we can add additional debug info to narrow this down further.

 

Bfir3: Can you follow the procedure in the OP to see whether the issue also points to AFD.SYS on your machine? (I do not think that AFD.SYS is the actual issue here. The issue may lie in the calls to that driver. ) Also, who is the manufacturer of your network adapter?

 

Edit: One more note: When you apply the procedure in the OP, you have to wait until Process Explorer shows only one thread named MediaBrowser.ServerApplication.exe with value 0x0. Let all the DLL calls terminate first. This may take a few minutes. Once this state is reached you will also find that the stack is no longer accessible. At this time you run the debug commands.

server-63638092801.txt

Edited by revengineer
Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted (edited)

Luke: here another log file starting after server reboot yesterday. The log posted above picks up at midnight. Combined, the logs give a ~12 hour period. But it is not required to run emby for this long to encounter the problem. I hope these help. Thanks for looking into this.

 

Question: Would "Enable Debug Logging" help?

server-63638076315.txt

Edited by revengineer
Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

One more thing: Process explorer lists the state of the MediaBrowser.ServerApplication as "Wait:Executive".

Link to comment
Share on other sites
bfir3

bfir3   114

Posted
Posted

I'm going to try this late tonight if I'm around. Don't want to disrupt any users during the day. I'll report back this weekend.

Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

@@revengineer can you please try removing all plugins except for backup and trailers. See if the issue persists. Thanks.

I have done that and will be reporting back. Considering history, the only plugin I had installed since the very beginning when I first encountered the shutdown problem is Coverart. But we shall see...

Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted (edited)

Luke: I confirm that the issue still exists with only the backup and trailer plugins installed. Log and screenshot from Process Explorer attached.

server-63638144920.txt

post-73883-0-97015500-1502583260_thumb.png

Edited by revengineer
Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

Repeated test: Ran emby overnight, nobody watched content and there were no recordings. This morning MediaBrowser.ServerApplication.exe process would not terminate. Only backup and trailer plugins were installed.

Link to comment
Share on other sites
  • 4 months later...
revengineer

revengineer   127

Posted
  • Author
Posted

Search of shutdown issues due to AFD.SYS seemed to point to issues with the network stack. So I did an experiment replacing the onboard Realtek NIC with an INTEL NIC with separate driver and, I assume, network stack. Unfortunately, this did not resolve the issue, and it still exists with the .net core version both running as service and as regular app. So this does not seems to be an issue with hardware or OS; this is a bug in the emby server software.

 

The excessive server reboots resulting from this issue remain my #1 gripe about emby. Do you have an update on your end? 

Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

Yes, Luke, I am running 3.2.60. I have checked every version since the above report and they all have this problem. I am often able to shut down emby server when it was just started, but once it has run for a while, this is no longer possible.

Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

Log is attached. Last log entry is 

2017-12-30 17:21:08.008 Info App: Disposing DlnaEntryPoint 

I believe this has not changed since the original report of the issue. After shutting down emby server, I waited more than an hour before I finally rebooted the hardware. Let me know if you spot something that points to the problem.

Log.txt

Link to comment
Share on other sites
Luke Emby Team

Luke   37216

Posted
Posted

It will. In the meantime you can try disabling the dlna server and dlna play to feature. They shut down. Then start back up and see if anything changes.

 

And or try those two features one at a time. Based on the log it looks like it might be related to one of those two. Thanks.

Link to comment
Share on other sites
  • 3 weeks later...
revengineer

revengineer   127

Posted
  • Author
Posted

With the release of 3.2.70 I was able to continue testing. During the update process I had to restart multiple time due to plugin updates. In that process I got the the shutdown to stall. Below are the last entries of the log file. I rebootet the server at 19:40, so roughly 13 minutes after the last log entry. Does this help? Or do we need more log statements?

2018-01-18 19:26:55.588 Info App: Disposing DlnaProfileEntryPoint
2018-01-18 19:26:55.588 Info App: Disposing DlnaEntryPoint
2018-01-18 19:26:55.589 Info Dlna: Disposing DeviceDiscovery
2018-01-18 19:26:55.591 Info Dlna: Disposing SsdpCommunicationsServer
2018-01-18 19:26:55.591 Info Dlna: SsdpCommunicationsServer disposing _BroadcastListenSocket.
2018-01-18 19:26:55.593 Info Dlna: SsdpCommunicationsServer disposing sendSocket
Link to comment
Share on other sites
revengineer

revengineer   127

Posted
  • Author
Posted

Great, then I am cautiously optimistic that we (you) are getting to the bottom of this. I just tested again. This time I waited 1+ hours prior to rebooting. After the reboot, the last lines of the previous log file were the same as above.

 

Interestingly, I have all the DLNA stuff disabled in emby server, so not sure why there are DLNA actions in the log file. 

 

Let me know when you pin point the issue. After chasing ghosts for 2+ years, I am curious.

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share
Go to topic listing
×
×
  • Create New...