Developer forum

Hi Nuno,

I have not seen that happen before.

Could it be caused by some deployment which has been configured to delete files in target folders which does not exist at the source?

Also, some file sync tools, like dropbox, have been reported to "randomly delete files". I have not experienced that myself, but it might be worth checking if some file sync is being used.

If you have access to the server then you can set up auditing for specific folders or files in Windows. That should give you some entries in the event log which you can use to find out when this is happening and if it is casued by something in Dynamicweb or some other process.

/Morten

Hi Morten,

I will let our sysadmin take a closer look. Good to know there's nothing that DW would do about it nor that there are any reports.

Nuno

Hi Morten,

I have more news on this. The files are not deleted after all, but it just looks like it. Take a look here https://www.screencast.com/t/lWNiC6yMw8

We only started seeing this since 9.5 (multiple solutions now). And it impacts the usage of the Repository/query. Not sure what's going on. This is the error we got from Event Log

If we run it manually there no issues, and the fact it shows as "Never built" instead of "Failed" left us puzzled for days. I am not sure if the issue is in our custom development or the core product when triggering it. Can you help us figure it out?

Best Regards,

Nuno Aguiar

1) Object reference not set to an instance of an object.  
Resulting in: An exception occurred while trying to create an instance of type 'Dna.IndexBuilderExtender.IndexBuilderExtender'.  
Resulting in: Cannot activate part 'Dna.IndexBuilderExtender.IndexBuilderExtender'.
Element: Dna.IndexBuilderExtender.IndexBuilderExtender -->  
Dna.IndexBuilderExtender.IndexBuilderExtender -->  
DirectoryCatalog (Path="c:\Domains\Sites\componenthardware.com\Application\bin") 

Check the code of the yellow part. Using httpcontext or something??

Hi Nicolai,

Got it, we saw that afterwards. We added some try-catch and logged the exceptions so we can catch it (we're not using HttpContext - this just started to happen after an upgrade to 9.5). If it turns out to be something DW could help with we'll let you know.

Best Regards,

Nuno Aguiar

We had the same issue again recently and upon analyzing the logs I found this:

Case 1
2019-03-05 19:05:16.898: Starting processing users.
2019-03-05 19:05:16.930: Starting processing users.
2019-03-05 19:05:17.008: Handling users
2019-03-05 19:05:47.100: Users index builder experienced a fatal error.. System.IO.IOException: The process cannot access the file 'c:\Domains\Sites\componenthardware.com\Files\System\Diagnostics\Secondary users\Users.index\Users\2019-03-05 190510\Status.xml' because it is being used by another process.    at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)    at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, String msgPath, Boolean bFromProxy)    at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, Boolean useAsync)    at System.Xml.XmlWriterSettings.CreateWriter(String outputFileName)    at System.Xml.Linq.XDocument.Save(String fileName, SaveOptions options)    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.ProcessUsers()    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.Build(IIndexWriter writer, Tracker tracker)
2019-03-05 19:05:47.100: Users index builder experienced a fatal error.
2019-03-05 19:05:47.303: Failed (10 / 10738).
2019-03-05 19:05:47.303: Closing index writer.
2019-03-05 19:05:47.631: Closed index writer.

Case 2
2019-03-05 19:05:16.180: Opening index writer.
2019-03-05 19:05:16.336: Opened index writer
2019-03-05 19:05:16.773: Opening database connection.
2019-03-05 19:05:47.084: Users index builder experienced a fatal error.. System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out    at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)    at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)    at System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()    at System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()    at System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()    at System.Data.SqlClient.TdsParserStateObject.TryReadByteArray(Byte[] buff, Int32 offset, Int32 len, Int32& totalRead)    at System.Data.SqlClient.TdsParserStateObject.TryReadChar(Char& value)    at System.Data.SqlClient.TdsParser.TryReadPlpUnicodeCharsChunk(Char[] buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& charsRead)    at System.Data.SqlClient.TdsParser.TryReadPlpUnicodeChars(Char[]& buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& totalCharsRead)    at System.Data.SqlClient.TdsParser.TryReadSqlStringValue(SqlBuffer value, Byte type, Int32 length, Encoding encoding, Boolean isPlp, TdsParserStateObject stateObj)    at System.Data.SqlClient.TdsParser.TryReadSqlValue(SqlBuffer value, SqlMetaDataPriv md, Int32 length, TdsParserStateObject stateObj, SqlCommandColumnEncryptionSetting columnEncryptionOverride, String columnName)    at System.Data.SqlClient.SqlDataReader.TryReadColumnInternal(Int32 i, Boolean readHeaderOnly)    at System.Data.SqlClient.SqlDataReader.TryReadColumn(Int32 i, Boolean setTimeout, Boolean allowPartiallyReadColumn)    at System.Data.SqlClient.SqlDataReader.GetValueInternal(Int32 i)    at System.Data.SqlClient.SqlDataReader.GetValue(Int32 i)    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.ProcessUsers()    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.Build(IIndexWriter writer, Tracker tracker) ClientConnectionId:b00a9f3f-01b3-4d5e-98d5-9a3f79021811 Error Number:-2,State:0,Class:11
2019-03-05 19:05:47.084: Users index builder experienced a fatal error.
2019-03-05 19:05:47.303: Failed.

2019-03-05 19:05:16.180: Opening index writer.
2019-03-05 19:05:16.336: Opened index writer
2019-03-05 19:05:16.773: Opening database connection.
2019-03-05 19:05:47.084: Users index builder experienced a fatal error.. System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out    at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)    at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)    at System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()    at System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()    at System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()    at System.Data.SqlClient.TdsParserStateObject.TryReadByteArray(Byte[] buff, Int32 offset, Int32 len, Int32& totalRead)    at System.Data.SqlClient.TdsParserStateObject.TryReadChar(Char& value)    at System.Data.SqlClient.TdsParser.TryReadPlpUnicodeCharsChunk(Char[] buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& charsRead)    at System.Data.SqlClient.TdsParser.TryReadPlpUnicodeChars(Char[]& buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& totalCharsRead)    at System.Data.SqlClient.TdsParser.TryReadSqlStringValue(SqlBuffer value, Byte type, Int32 length, Encoding encoding, Boolean isPlp, TdsParserStateObject stateObj)    at System.Data.SqlClient.TdsParser.TryReadSqlValue(SqlBuffer value, SqlMetaDataPriv md, Int32 length, TdsParserStateObject stateObj, SqlCommandColumnEncryptionSetting columnEncryptionOverride, String columnName)    at System.Data.SqlClient.SqlDataReader.TryReadColumnInternal(Int32 i, Boolean readHeaderOnly)    at System.Data.SqlClient.SqlDataReader.TryReadColumn(Int32 i, Boolean setTimeout, Boolean allowPartiallyReadColumn)    at System.Data.SqlClient.SqlDataReader.GetValueInternal(Int32 i)    at System.Data.SqlClient.SqlDataReader.GetValue(Int32 i)    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.ProcessUsers()    at Dynamicweb.Security.UserManagement.Indexing.UserIndexBuilder.Build(IIndexWriter writer, Tracker tracker) ClientConnectionId:b00a9f3f-01b3-4d5e-98d5-9a3f79021811 Error Number:-2,State:0,Class:11
2019-03-05 19:05:47.084: Users index builder experienced a fatal error.
2019-03-05 19:05:47.303: Failed.

Would either of these exceptions explain why the file gets in a corrupt or "never built" state? Any chance these issues can be reproduced?

I can understand why we could get a SQL timeout and I think we should work on preventing that from happening in the first place on our end. But I'm not sure I understand why the diagnostics file would be locked though. Is there a way to turn of diagnostics so we can see if that makes the problem go away?

Thanks!

Imar

One further thought. Why do both instances fail? Shouldn't the 2nd instance not attempt to run if the first instance isn't in a healthy state? 

Scott

Hi Imar and Scott

Can we see a dump of the setup?

I see this in your case 1:

2019-03-05 19:05:16.898: Starting processing users.
2019-03-05 19:05:16.930: Starting processing users.

That is not good as it indicates that 2 things are running at the same time... that will probably cause problems.

BR Nicolai

Yep, here are some dumps:

1 - Setup of the failing index
2 - Task for the failing index (running way too often, but I don't think that's the real issue)
3 - Another repository on the same solution with an index with the same name (but different builds); adding it here just for completeness' sake

The site is: http://qa-abbycadabby.dw-demo.com

Thanks!

Hi Nuno, Scott and Imar,

I think we have multiple unrelated issues in this thread, but I'll try to comment on all of them

1) The 'Never build' problem

This doesn't usually mean that the index build has failed, it just means that we don't have any history of it being build. We get our history from the files inside Files/System/Diagnostics, and whatever subfolders matching the current index and instance. So if these files inside the folders are deleted, you'll end up seeing what you see.

I can see that you have enabled 'Automatic log deletion' with a retension of 1 day, so this could explain the behavior you are seeing. But I agree that when you have a retension of 1 day, you should always keep the logs from the last 24 hours, so unless the Index isn't build that often, so you should always keep something.

Could I get you to disable the 'Automatic log deletion' for Files/System/Diagnostics to see if it removes the problem?

2) Multiple build of the same instance running at the same time

It looks like you try to build the same index instance at the same time, which is probably not a good idea. This could lead to index being in a corrupt state, but I still think the main problem is (1).

I hope this solves the problem. 

Let me know, how it goes.

Best regards,

Steffen

I have disabled the log deletion. There are a lot more than 1 day of diagnostics logs available so I don't know that this is the issue. The repository is also rebuilt quite often. I have the log settings this agressive because with the amount of logging we do, the System tab becomes very slow due to the logs being loaded on access.

Thanks Steffen for the info. That's helpful to know about the log being the cause of one of the issues. That one sounds benign, but now we know what to watch for.

For the 2nd issue, we're still tracking down what is causing the simultaneous build. I believe that on this site we're just using the standard repository task, but we're still digging into that to confirm that we don't have some other method calling the rebuild. You've pointed us in the right direction to know where to look next.

Thanks,

Scott

I don't think it's us running two indexes at the same time. Take a look at this:

2019-03-05 19:05:16.898: Starting processing users.
2019-03-05 19:05:16.930: Starting processing users.

There's only a few milliseconds between the two calls. It sounds more like that indexing engine starting the two tasks simultaneously?

Imar

Hi,

I have some new information on this. This time it was the Products build that failed.

• The 'A' (primary) build seems to have been triggered twice within a few miliseconds apart
• The 'B' (secondary) build was triggered at the same time build 'A' was rebuilding, so it failed

Attached you can find the previous build's success logs (just FYI) and then both logs for the failed builds.

Can anyone please take a look at this?

Best Regards,

Nuno Aguiar

Hi,

Did anybody had a chance to take a look at this? It really seems like something that Dynamicweb needs to better handle on when to allow an instance to be rebuilt.

Best Regards,

Nuno Aguiar