Disconnected from OpenHistorian Server

mstucky · June 4, 2020, 8:42pm

I’ve been having an issue where the OpenHistorian server seems to stop working after it has been running for an extended period. The OpenHistorian service is still running when this happens, but I cannot access the browser interface. When I leave it running overnight for instance, I usually have to restart the machine before I can use it successfully.

Today, it stopped working while I was using it. I had a console open when it happened, so I’m hoping I may have enough information to help determine what’s causing the problem.

This is what I saw when it stopped working:

Further up in the console feed, there were multiple instances of this message:

[RTAC-DNP3] Begining task: Application Poll (INFO) @ c:\projects\dnp3\cpp\libs\src\opendnp3\master\mastercontext.cpp(400)

There were not enough free threads in the ThreadPool to complete the operation.

There were not enough free threads in the ThreadPool to complete the operation.

[RTAC-DNP3] Begining task: Application Poll (INFO) @ c:\projects\dnp3\cpp\libs\src\opendnp3\master\mastercontext.cpp(400)

There were also some entries in the ErrorLog.txt file. While there were several errors all generated within seconds of the others, they were all essentially identical to this one:

[6/4/2020 2:46:22 PM] Date and Time:         6/4/2020 2:46:22 PM
Machine Name:          SEL
Machine IP:            xxxx
Machine OS:            Microsoft Windows NT 6.2.9200.0

Application Domain:    openHistorian.exe
Assembly Codebase:     C:/Program Files/openHistorian/openHistorian.exe
Assembly Full Name:    openHistorian, Version=2.7.195.0, Culture=neutral, PublicKeyToken=null
Assembly Version:      2.7.195.0
Assembly Build Date:   5/5/2020 6:22:56 PM
.Net Runtime Version:  4.0.30319.42000

Exception Source:      GSF.SortedTreeStore
Exception Type:        System.Exception
Exception Message:     Out of free space
Exception Target Site: GetPathWithEnoughSpace

---- Stack Trace ----
   GSF.Snap.Services.Writer.SimplifiedArchiveInitializer`2.GetPathWithEnoughSpace(estimatedSize As Int64)
       openHistorian.exe: N 00282
   GSF.Snap.Services.Writer.SimplifiedArchiveInitializer`2.CreateArchiveFile(startKey As TKey, endKey As TKey, estimatedSize As Int64, data As TreeStream`2, archiveIdCallback As Action`1)
       openHistorian.exe: N 00053
   GSF.Snap.Services.Wri

When I attempted to restart the OpenHistorian service, the following error was generated:

Restart Service

Any insight into what may be causing this would be appreciated! One item that came to mind is that there is another server running on localhost (SEL SynchroWave Central). However, that is running on the default port rather than 8180. I’m not familiar enough with such things to know if that could cause a conflict with results like this or not.

ritchiecarroll · June 5, 2020, 1:07pm

Looks like you are out of disk space? Can you check the disk space where openHistorian is installed?

You will need to turn on some of the self-curtailment operations unless you have another disk.

Ritchie

mstucky · June 5, 2020, 1:23pm

That’s what is strange… the disk where it is installed has 211 GB of free space.

ritchiecarroll · June 5, 2020, 1:34pm

The open historian has a default setting to attempt to reserve 500GB on the target archive directory.

To use more, add a setting similar to the following in the openHistorian connection string:

; desiredRemainingSpace=10

The setting value above says to reserve only 10GB of remaining space on the drive. You can find the connection string in the openHistorian Manager (UI application) under Outputs / Historian Instances. After adding the setting click Save then Initialize or restart the service.

Also, you will likely want to add another setting to make sure the total size of the archive is self-maintained. The MaximumArchiveDays setting will make sure that only the specified number of days exist in the archive.

Ritchie

mstucky · June 5, 2020, 1:49pm

The archive directory is not very big yet, as I’ve only been successfully polling for about a week now, and only intermittently due to the issue above. Here is current size:

Archive

Restarting the computer resolves the issue temporarily.

ritchiecarroll · June 5, 2020, 1:55pm

Can you provide current connection string for openHistorian? Also, if you can provide the ErrorLog.txt that may provide some clues. You can upload here:

https://upload.gridprotectionalliance.org/Upload/OHDisconnectLog/

Just let me know when you upload so I can go take a look.

Thanks,
Ritchie

mstucky · June 5, 2020, 2:10pm

I think this is the connection string you’re referring to - let me know if you had something else in mind. I uploaded the ErrorLog file to the link you provided.

ritchiecarroll · June 5, 2020, 2:16pm

That helps - thanks - looks like connection string is blank, which means everything is using the default settings.

While I look at your error log, I would recommend adding the following to the connection string:

desiredRemainingSpace=10; maximumArchiveDays=100

Then click Save and Initialize. You can adjust these settings later if you find you can archive more than 100 days of data.

Thanks,
Ritchie

ritchiecarroll · June 5, 2020, 3:15pm

So the error log is just the same message over and over, out of space.

I think the next best step is to apply the changes to connection string I mentioned above and report back.

Thanks,
Ritchie

mstucky · June 5, 2020, 3:29pm

Thanks for looking at this! I’ve updated the connection string as suggested, and I’ll report back with results after it’s been running long enough to see if behavior has changed.

mstucky · June 11, 2020, 3:51pm

After updating the connection string as noted, I’m still having server stability problems, but I have not seen any more error logs about being out of space. For the most recent freeze, I have some additional detail which may help.

I was viewing data in Grafana when it became unresponsive (around 9:25am) and it displayed several alerts saying “Annotation Query Failed / Internal Server Error”. However, the DNP3 adapter was apparently still working at that point because I logged into the connected RTAC and I could see that it was still getting polled by the OH computer.

After restarting the OH machine, the Grafana graph of the test data showed that OH was still receiving and recording DNP data for about 10 minutes after the web server became unresponsive:

Capture (2)

I checked the error log for entries from today, and this was the first:

[6/11/2020 9:22:37 AM] Date and Time:         6/11/2020 9:22:37 AM
Machine Name:          SEL
Machine IP:            xxxx
Machine OS:            Microsoft Windows NT 6.2.9200.0

Application Domain:    openHistorian.exe
Assembly Codebase:     C:/Program Files/openHistorian/openHistorian.exe
Assembly Full Name:    openHistorian, Version=2.7.195.0, Culture=neutral, PublicKeyToken=null
Assembly Version:      2.7.195.0
Assembly Build Date:   5/5/2020 6:22:56 PM
.Net Runtime Version:  4.0.30319.42000

Exception Source:      System
Exception Type:        System.InvalidOperationException
Exception Message:     There were not enough free threads in the ThreadPool to complete the operation.
Exception Target Site: BeginGetResponse

---- Stack Trace ----
   System.Net.HttpWebRequest.BeginGetResponse(callback As AsyncCallback, state As Object)
       openHistorian.exe: N 00514
   System.Net.Http.HttpClientHandler.StartGettingResponse(state As RequestState)
       openHistorian.exe: N 00082
   System.Net.Http.HttpClientHandler.StartRequest(obj As Object)
       openHistorian.exe: N 00084
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   openHistorian.Adapters.<ProxyPage>d__9.MoveNext()
       openHistorian.exe: N 01090
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Threading.Tasks.<CastToObject>d__1`1.MoveNext()
       openHistorian.exe: N 00234
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.Controllers.<InvokeActionAsyncCore>d__1.MoveNext()
       openHistorian.exe: N 00300
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.Filters.<CallOnActionExecutedAsync>d__6.MoveNext()
       openHistorian.exe: N 00307
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Web.Http.Filters.<CallOnActionExecutedAsync>d__6.MoveNext()
       openHistorian.exe: N 00729
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.Filters.<ExecuteActionFilterAsyncCore>d__5.MoveNext()
       openHistorian.exe: N 00435
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.Controllers.<ExecuteAsync>d__5.MoveNext()
       openHistorian.exe: N 00881
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.Dispatcher.<SendAsync>d__15.MoveNext()
       openHistorian.exe: N 00657
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Web.Http.Dispatcher.<SendAsync>d__15.MoveNext()
       openHistorian.exe: N 01169
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   GSF.Web.Security.<SendAsync>d__13.MoveNext()
       openHistorian.exe: N 00553
   System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
       openHistorian.exe: N 00032
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(task As Task)
       openHistorian.exe: N 00062
   System.Web.Http.<SendAsync>d__24.MoveNext()
       openHistorian.exe: N 00554

There were several more errors recorded subsequent to this, but all the same error.

Any ideas?

Thanks,
Mark

ritchiecarroll · June 11, 2020, 3:56pm

What are the specs on the system you are running this on? Interesting error about not enough free threads - haven’t seen that one before.

Thanks,
Ritchie

mstucky · June 11, 2020, 4:13pm

Here is a clipping from system info:

Capture (3)

StephenCWills · June 11, 2020, 4:25pm

Is the one RTAC the only device providing data to the historian?

mstucky · June 11, 2020, 4:27pm

Yes, that’s correct.

StephenCWills · June 11, 2020, 4:28pm

About how long was the system running before it became unresponsive?

mstucky · June 11, 2020, 4:32pm

Roughly 40 minutes. If you look at the grafana chart above, the initial spike ramping up to 400A was the first test data I sent after restarting the machine.

ritchiecarroll · June 11, 2020, 5:00pm

We are looking into this, we don’t test the DNP3 adapter as much as other tools - so we are looking here first.

mstucky · June 11, 2020, 6:04pm

Thanks! I appreciate your assistance!

mstucky · June 15, 2020, 4:39pm

Because of the error that was generated, I was curious about the number of threads OpenHistorian is using on this system. So I checked this morning, and windows task manager shows openhistorian.exe (openHistorian Iaon Host) using 2,121 threads. In comparison, I’ve seen the openHistorian installed on my home laptop using only 68 threads at most, usually hovering between 60 and 65. I don’t know if this is useful info or not, but thought I would pass it on.