Hello,

I started to log activity (See the post)

Today I try to index the reqid field as primary key ( +/- 500.000 records ) but it failed ( the key is not unique ? )

Do you have any blank or deleted records?

Thank you for your reply Tore, yes now it's ok for the wwrequestlog.dbf

Here is the query string

Processing Error - Server Startup

<PRE>
     Error: 1733
   Message: Class definition RESTPROCESSCONFIG is not found.
   Details: RESTPROCESSCONFIG
            Code inside of Server OnInit() failed
      Code: THIS.orestprocess = CREATEOBJECT("restprocessConfig")
   Program: init
   Line No: 376

Handled by: Greenshopserver.OnError()<br>
</PRE>

Since reqid is a primary key, it can't contain blank in more than one record. Either delete the blank records followed by a Pack, or fill the blank reqid fields with some random and unique data.

Also you should investigate why the blank records ended up there.

Only reqid was left blank and it seems it was a server startup error that's web connection code..

ReqId is not a primary key, it's just a value unless you make it a PK yourself. wwRequestLog.dbf doesn't have an index to minimize overhead since it's just a request stream of data.

The ReqId is the Web Connection Handler id that identifies a request and it'll always be written assuming the server gets that far. But if an error occurs during startup it never gets a request id and hence there's no id written to the table.

IOW, don't make any assumptions about the ReqId (or any other field) in the table if you use it for your own purposes. The error itself (missing configuration) appears to be something different related to a missing configuration class (perhaps renamed and not adjusted in the config?)

+++ Rick ---

Ok, thank you for the clarification !

My activity log reports indeed some strange data. Same reqid for different session and dates and the request is not in wwRequestLog.dbf file ? This is the code in OnProcessInit

		THIS.LogActivity(REQUEST.GetRequestId(),THIS.oSession.cSessionId,THIS.cPage,THIS.cAuthenticatedUserId)   

I have no idea how that is possible. Each request generates a new request id that is based on a GUID (partial Guid) so the values are going to be very random. There's no way that the same id can be generated more than once nor should that ever stick.

The only thing I can think of is that somehow a request is sticking but these IDs are a long time apart.

No idea how that could be possible.

ISAPI or .NET Module? What version?

+++ Rick ---

Net Module and Web Connection 6

Are you sure you're running your COM server in Single Instance not multi-threaded? If you're using multi-threaded EXE COM servers, you will end up corrupting memory and that might account for this. Other than that I honestly have no idea - this should never happen and I've never seen this sort of thing.

+++ Rick ---

Yes, only one instance is started. It seems there are 3 replicated reqid ( see bellow) , and each block of tree has +/- the same time stamp. I remember now why these request are not the wwrequestlog.dbf From 24/08 to 27/08 I made a number a code update and the complete deploy dir was override ( including the wwrequestlog.dbf )

To be honest I have no idea what's happening with your code because those IDs look all wrong.

The code I use to create the ids is:

// Generate a new RequestId            
RequestId = Thread.CurrentThread.ManagedThreadId + "_" +
            Guid.NewGuid().GetHashCode().ToString("x");

which means the thread id may very well stay steady for a single instance, but the rest of the string should be completely different each and every time you hit the server. In your case that's not happening - more of the second string are the same. So I'm not sure whether you are in fact using the module. I think the ISAPI handler uses a different algo that involves the process, thread and then some random characters tacked on - that looks like a more likely candidate given the Ids you're showing here. But even ISAPI generates a new ID on every request.

The id is generated on every request that comes into the server.

Either way I don't see how it's possible to ever duplicate ids unless there's something fundamentally wrong with the processing (ie. corrupt memory) or these request ids are getting created from some internal processing that isn't firing from a request (maybe you have a timer that fires off tasks and these tasks are stuck on an old request id?).

The only way memory can corrupt on requests is running in an invalid COM mode - multithreaded COM exe for example or single threaded dll. Both of those modes will corrupt COM memory and will cause major failures. Make sure you are run single threaded EXE COM servers which is what Web Connection is designed for and what is the default for EXE COM servers.

+++ Rick ---

I am using a timer in a observer design pattern to log error's but also to log some key user event and erverything was running fine when the duplicated reqid appears. The code update done in 08/2018 was to be GDPR compliant on the Web store, here are the users message (LOG-MSG) event at a time around duplicated Requestid

**The mystery for me is how and where did your code memorize these tree IDs 4 days and give a lot of unique IDs between 😃 **
Here is the complete code between the REQUEST.GetRequestId() and the fox table.

FUNCTION OnProcessInit
THIS.LogActivity(REQUEST.GetRequestId(),THIS.oSession.cSessionId,THIS.cPage,THIS.cAuthenticatedUserId)   && Varchar 17
ENDFUNC 

FUNCTION LogActivity

		LPARAMETERS tcReqId,tcSessionId,tcPage,tcUserId

		IF !USED("ActivityLog")
			USE (SERVER.oConfig.cSystemFilesDataPath+"wwActivityLog.dbf") AGAIN SHARED IN 0 ALIAS ActivityLog
			*-* USE (CONFIG.cDataPath+"ww_ActiLog") AGAIN SHARED IN 0 ALIAS ActivityLog
		ENDIF

		INSERT INTO ActivityLog ;
			(ReqId,SessionId,USERID,PAGE,entered) ;
			VALUES (tcReqId,tcSessionId,tcUserId,LOWER(tcPage),DATETIME())

	ENDFUNC

Well if you're using a timer you're not using the stock logging, so it's possible the timer is the cause of the problem. Maybe the time gets stuck when the server is too busy or there is some other scoping issue where reqId is being cached improperly.

IAC, if you're logging differently than the normal happy path it's very likely the issue is in that code as I can't think of a single scenario from within Web Connection's sequential and transactional code that would allow the request id to not get re-generated on every incoming request.

If you are serious about tracking this down, turn on verbose logging in the DLL and check the request ids that are getting generated. Import into a db and check for duplicates. It's highly unlikely you'll see dupes (although technically possible based on the partial guid, but never with two inflight requests at the same time given the pinned thread id).

+++ Rick ---

The timer is only used to publish selected events ( every 2 seconds ) and i use the Web Connection code to Login / Logout why is this incompatible ? ( maybe I misunderstand "stock logging" )

Please note also the delay in IDs replication ( 4 Days max ) the Foxpro Web Connection part was shutdown more than ones ( maybe 12 code update ) so how could the IDs being cached improperly in foxpro .. ?

The IIS was not restarted ...

It's also strange that the id replication occurs with same name method ( 2 with Login and one with recipies_post ).

It's not critical to track it down for me now, server is more quiet now since we blacklisted some IPs ( Most of the login actvity was malware activity ). But if I run a test I will be stress the server and put the WebConnection foxpro server on and off and compare verbose logging from the DLL with wwrequestlog.dbf. Thank you for the suggestion !

Just a wild guess. Set Carry On?

SET CARRY is off and there are +/- 4000 records between replicated IDs, the index was created off line on a copy for testing purpose, here is the natural order. One of the duplicated IDs is selected

It's very clear here that everytimes the Foxpro server commes up after a average of +/-2 minutes down he received +/- ten requests in the same second and these requests always include 3 replicated requestid with the same page name

ETC...

That's probably your timer firing when the application gets idle and firing backed up events.

+++ Rick ---

No it's not my timer but the wwfiletimer

Gsforumprocess.onprocessinit
Gsforumprocess.process
Gsforumprocess
Greenshopserver.process
Greenshopserver.processhit
Greenshopserver.tmrfiletimer.timer
Greenshopmain

Well I can see how you could end up at least with two log entries as you're accessing two separate process classes.

IAC I don't know what the issue is in your specific use case, but I am sure that there's no way actual incoming requests are feeding you duplicate request ids - something internal in the app is either caching the value or refiring events in some way that's causing those duplicated.

As I said - turn on logging int he DLL and you should be able to verify the actual request ids getting generated as part of each request and passed into the application.

Plus - are you running file based in production? That's probably not such a good idea...

+++ Rick ---

Just curious, if we consider that the same request is cached somewhere and "processed" 12 times does this imply that somebody somewhere received 12 respons for the same request with a 4 days delay for the last one ?

Well that depends on what's actually happening with your request duplication.

I'm pretty certain that this is caused by your additional timer logic running that is diverting the file timer.

Simple thing to do is run in COM mode and take the request timer processing out of the equation.

You shouldn't be running file mode in production anyway.

+++ Rick ---