Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Hey John, we ended up testing different things, I didn't ever get too far
into the memory side. (Thanks for that, good to know.) I retested again
last night and I can kill 4D from entirely legal code. I'll show you at
dinner, if you like. There is a *concurrency bug*.

I'm not convinced that everyone at 4D fully grasps the nature of a
concurrency bug and they're definitely not grasping their importance. It's
an existential bug. What's going on should be *impossible*. I don't mean
rare (it is rare, but not that rare.) There's a _reason_ I've reported this
bug and have been going on about it. When do I normally do that? I don't.
And it is extremely unlikely that I ever will again. There's a margin in
doing so, but it's pretty much all negative margin ;-)

They should email Laurent E., he understands concurrency perfectly and
should appreciate the situation. Plus, I think this feature set comes from
him. It's possible Engineering will discover that it's a highly specific
and localized bug, not a more generalized bug - let's hope so. But there is
*no* way for us to know that on the outside. I could keep probing to get a
better sense of the shape of the bug, but that's a massive misuse of my
time. I've got real work to do. So, no logging to files via a worker in 4D
for me :( I think that I can still use normal processes to do a
record-based passthrough, but that's a very different performance
proposition entirely. (There's no way that I can use that approach for the
Web logs, I've killed 4D before that way...not doing it again.)
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[John Baughman via 4D_Tech]

One thing I forgot to mention/ask…

David’s test routine runs significantly faster with 32-bit 4D than it does with 
64-bit 4D. Any ideas as to why this might be the case?

To refresh memories as to what the test is doing…

For ($1;1;10)
  $prsNum:=New Process(“TestProcess”.0;”TestProcess”)
end for 

//TestProcess method
For ($1;1;100)
  CALL WORKER(“LogWorker”;“LogWorker_Write”;$i)

end for 

//LogWorker
  SEND PACKET(Log_DocRef;$1+Char(Carriage return))

So the test is calling the worker 10 million times. Since nearly all of the 
calls are going into the worker queue, I believe it is the for loops that are 
executing more slowly with 64-bit 4D. The interaction with the file, SEND 
PACKET, appears to be plodding along at the same pace. 

> On Oct 11, 2017, at 6:46 AM, John Baughman  wrote:
> 
> Got an email from Timothy Penner yesterday pointing out that in his testing 
> of this issue he has concluded that the crash occurs because 4D is being 
> pushed past it’s memory limits. That is if run using the 32bit version of 4D. 
> Tim suggested that we run the test using the 64 bit version of 4D.
> 
> Running the test using 64-bit 4D v16 R4, the test does not crash. Thanks Tim!
> 
> I think this explains everything. Running with 32 bit 4D in a 64 bit OS I 
> think we have a 4 GB memory limit which I think would be easily reached as 
> the worker queue goes over 2.1 million calls.
> 
> With 4D 64-bit I think we have a 16 TB memory limit… no problem running the 
> test up to 100 million calls in the queue.
> 
> My conclusion: 
> 
> 1. There is no queue limit that we know of except those dictated by memory 
> constraints.
> 2. There is no bug or memory leak.
> 3. We still need a way to monitor the queue size especially if a worker is 
> expected to be flooded with calls.
> 
> It was interesting watching the test run to it’s end, as the test completes 
> in a relatively short period of time, but the text file continues to build 
> for several hours as the worker continues to consume it’s queue.
> 
> John
> 
>> On Oct 8, 2017, at 8:42 PM, John Baughman  wrote:
>> 
>> 
>>> On Oct 8, 2017, at 5:53 PM, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
>>> wrote:
>>> 
>>> Oh, I forgot to say earlier about John's finding of ~2.1M messages being a
>>> kind of breaking point...that number may not be replicable in other tests.
>>> You might find a different number. The payloads in my scratch database are
>>> quite small. For all I know, if you made the payloads 10x bigger, you would
>>> crash with ~210K messages. I won't be testing this myself.
>> 
>> Why not test this. I added a bit of text to the log entry with the 2 million 
>> calls set to run...
>> 
>> $text:=“”  No crash. Only an index number is being logged, ie, 1, 2, 3, etc.
>> $text:=“j”*16  No problem
>> $text:=“j”*32 Crashes near the end
>> 
>> Here is the kicker. If I am running interpreted with the Runtime Explorer 
>> open it crashes very early and the Runtime Explorer throws an array range 
>> error on occasion before 4D crashes. Sometimes with $text:=“j”*32 set it 
>> actually completes, but if I try to open the Runtime Explorer, 4D crashes.
>> 
>> Now I ‘m thinking maybe it’s not the worker queue limit per say but a memory 
>> leak associated with the worker and/or it’s queue.
>> 
>> John
>> 
>> 
>> 
>> 
>> John Baughman
>> Kailua, Hawaii
>> (808) 262-0328
>> john...@hawaii.rr.com
>> 
>> 
>> 
>> 
>> 
> 
> John Baughman
> Kailua, Hawaii
> (808) 262-0328
> john...@hawaii.rr.com

John Baughman
Kailua, Hawaii
(808) 262-0328
john...@hawaii.rr.com





**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[John Baughman via 4D_Tech]

Got an email from Timothy Penner yesterday pointing out that in his testing of 
this issue he has concluded that the crash occurs because 4D is being pushed 
past it’s memory limits. That is if run using the 32bit version of 4D. Tim 
suggested that we run the test using the 64 bit version of 4D.

Running the test using 64-bit 4D v16 R4, the test does not crash. Thanks Tim!

I think this explains everything. Running with 32 bit 4D in a 64 bit OS I think 
we have a 4 GB memory limit which I think would be easily reached as the worker 
queue goes over 2.1 million calls.

With 4D 64-bit I think we have a 16 TB memory limit… no problem running the 
test up to 100 million calls in the queue.

My conclusion: 

1. There is no queue limit that we know of except those dictated by memory 
constraints.
2. There is no bug or memory leak.
3. We still need a way to monitor the queue size especially if a worker is 
expected to be flooded with calls.

It was interesting watching the test run to it’s end, as the test completes in 
a relatively short period of time, but the text file continues to build for 
several hours as the worker continues to consume it’s queue.

John

> On Oct 8, 2017, at 8:42 PM, John Baughman  wrote:
> 
> 
>> On Oct 8, 2017, at 5:53 PM, David Adams via 4D_Tech <4d_tech@lists.4d.com 
>> > wrote:
>> 
>> Oh, I forgot to say earlier about John's finding of ~2.1M messages being a
>> kind of breaking point...that number may not be replicable in other tests.
>> You might find a different number. The payloads in my scratch database are
>> quite small. For all I know, if you made the payloads 10x bigger, you would
>> crash with ~210K messages. I won't be testing this myself.
> 
> Why not test this. I added a bit of text to the log entry with the 2 million 
> calls set to run...
> 
> $text:=“”  No crash. Only an index number is being logged, ie, 1, 2, 3, etc.
> $text:=“j”*16  No problem
> $text:=“j”*32 Crashes near the end
> 
> Here is the kicker. If I am running interpreted with the Runtime Explorer 
> open it crashes very early and the Runtime Explorer throws an array range 
> error on occasion before 4D crashes. Sometimes with $text:=“j”*32 set it 
> actually completes, but if I try to open the Runtime Explorer, 4D crashes.
> 
> Now I ‘m thinking maybe it’s not the worker queue limit per say but a memory 
> leak associated with the worker and/or it’s queue.
> 
> John
> 
> 
> 
> 
> John Baughman
> Kailua, Hawaii
> (808) 262-0328
> john...@hawaii.rr.com 
> 
> 
> 
> 
> 

John Baughman
Kailua, Hawaii
(808) 262-0328
john...@hawaii.rr.com





**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Chip Scheide via 4D_Tech]

question:
was your IP var a longint?, Real?, or Doublelong (whatever it is 
called)?

This might make some difference to your testing.. BUT... based on your 
discovered size limit, it seems that the Worker Queue is limited by 
some internal reference to a long integer... MaxLong being 
approximately 2.1 billion

On Sun, 8 Oct 2017 16:20:58 -1000, John Baughman via 4D_Tech wrote:
> 
> Worker processes only handle 1 call at a time, creating a queue 
> of calls which are handled in turn. I found that the LogWriter test 
> was rapidly maintaining a huge queue growing to over 100,000 calls 
> almost instantly. The crash occurred when the queue reached something 
> in the neighborhood of 2.1 million calls, approximately 2,101,000 
> calls. This was 100% repeatable.
---
Gas is for washing parts
Alcohol is for drinkin'
Nitromethane is for racing 
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

> As a side note, I am sure you are aware of this, but by killing the
worker every 100,000 calls, out of the 2 million calls
> nearly all of the log entries are missed as they are in the queue when
the worker is killed. I am getting at most 24,000
> log entries in the text file.

I've lost track, but I think that this was the very thing I was testing -
the %/# of lost log lines I would end up getting.

The more I think about it, the more I'm convinced that what I'm trying to
do simply isn't part of the designed capacity of 4D's system. I can live
with that, I'll just move the logging out of 4D. I may lose something that
way (a bit of data that would come from a 4D looking that could inject some
extra data) and it's a pity, but 4D never promised me a log writer. It's
just not sufficient to requirement.

So, checking what NGNIX offers. On the log enrichment side, Loggly offers,
well, very little but I'll be checking out SumoLogic down the road and that
looks a whole lot better. (It's a Splunk clone, as far as I can see, but
cheaper.)
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[John Baughman via 4D_Tech]

> On Oct 8, 2017, at 5:53 PM, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
> wrote:
> 
> Oh, I forgot to say earlier about John's finding of ~2.1M messages being a
> kind of breaking point...that number may not be replicable in other tests.
> You might find a different number. The payloads in my scratch database are
> quite small. For all I know, if you made the payloads 10x bigger, you would
> crash with ~210K messages. I won't be testing this myself.

Why not test this. I added a bit of text to the log entry with the 2 million 
calls set to run...

$text:=“”  No crash. Only an index number is being logged, ie, 1, 2, 3, etc.
$text:=“j”*16  No problem
$text:=“j”*32 Crashes near the end

Here is the kicker. If I am running interpreted with the Runtime Explorer open 
it crashes very early and the Runtime Explorer throws an array range error on 
occasion before 4D crashes. Sometimes with $text:=“j”*32 set it actually 
completes, but if I try to open the Runtime Explorer, 4D crashes.

Now I ‘m thinking maybe it’s not the worker queue limit per say but a memory 
leak associated with the worker and/or it’s queue.

John




John Baughman
Kailua, Hawaii
(808) 262-0328
john...@hawaii.rr.com





**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[John Baughman via 4D_Tech]

> Once it happens, you get all kinds of weird stuff -
> duplicate workers with "unique" names, the runtime monitor gets super buggy
> and starts throwing range errors...until you're dead. If you *don't* find
> this result on your gear, please post what version of 4D you're testing
> with.

Yes I have seen this happen, but only for various reasons of my doing like 
killing the worker in the Runtime Explorer without first closing the document. 


> On Oct 8, 2017, at 5:53 PM, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
> wrote:
> 
> Just try out a compiled version of the original database I sent without any
> of your modifications and let it run for a couple of minutes.

I have done that and it just crashes. My testing has convinced me that the 
crash is the result of the queue reaching it’s limit. Nothing to do with CLOSE 
DOCUMENT.

Try this… Take your copy of the original database and in 
LogWorker_CallABunch_Coop and in LogWorker_CallABunch_Preemptive change $count 
to 20. That will be 2 million calls to the worker. Do not change anything 
else. For me the test runs without crashing compiled both cooperative and 
preemptive. I have run it several times. It is not a 100 million calls but If 
CLOSE DOCUMENT were in fact an issue I think it would have shown up in 2 
million calls.

As a side note, I am sure you are aware of this, but by killing the worker 
every 100,000 calls, out of the 2 million calls nearly all of the log entries 
are missed as they are in the queue when the worker is killed. I am getting at 
most 24,000 log entries in the text file.

I am running 4D v16 R4 on a MacBook Pro with High Sierra. tested good with 16.2

John


John Baughman
Kailua, Hawaii
(808) 262-0328
john...@hawaii.rr.com





**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Add,

On the entirely likely chance that my first answer sounded insufferably
arrogant - just wanted to addWell, I'm sleep deprived like I can't
remember, and massively jet lagged. I was trying to say that this whole
area is one of my *few* areas of genuine expertise. I don't have many. Just
ask anyone ;-) It's just an accident of personal history that this is one
of my areas of interest and experience - there are *tons* of equally
important things that I'm clueless about. So, not trying to be a jerk about
it, but I figure it was worth giving you the background that I'm not
figuring any of these things out from scratch at this point...only figuring
out how to implement things within 4D's feature set.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

> I understand your thinking that 4D may not the way to go for event
logging,
> but your concern about CLOSE DOCUMENT is where we do not agree. I'am sure
you
> have seen CLOSE DOCUMENT fail, but I suspect that what you are seeing is
not
> an issue with CLOSE DOCUMENT, but something else not readily apparent. I
think
> you said at some point that 4D has recognized this as a bug, but I still
> question whether in fact it is.

Yes, you're absolutely right on this point. I don't know what the bug is.
It *manifests* as an impossible file lock error, but I think it's very,
very likely that this is a symptom of something else. Either way, it's a
show-stopper for me and I can't fix it.

> Perhaps you can show me in the sample database how to make CLOSE DOCUMENT
fail
> or have another database that demonstrates the problem?

That one already shows the problem. I've reproduced it, as has 4D and a
couple of other people. Once it happens, you get all kinds of weird stuff -
duplicate workers with "unique" names, the runtime monitor gets super buggy
and starts throwing range errors...until you're dead. If you *don't* find
this result on your gear, please post what version of 4D you're testing
with.

>> When I saw your initial post in this regard, I jumped in because I do a
lot of
> work that involves the opening and closing of documents. If a problem
exists I
> really need to know about it. Thus far my testing based on your posts has
not
> demonstrated anything that has caused me to doubt that CLOSE DOCUMENT
will in
> fact close a file.

Just try out a compiled version of the original database I sent without any
of your modifications and let it run for a couple of minutes.

Oh, I forgot to say earlier about John's finding of ~2.1M messages being a
kind of breaking point...that number may not be replicable in other tests.
You might find a different number. The payloads in my scratch database are
quite small. For all I know, if you made the payloads 10x bigger, you would
crash with ~210K messages. I won't be testing this myself.


On Mon, Oct 9, 2017 at 3:33 AM, John Baughman via 4D_Tech <
4d_tech@lists.4d.com> wrote:

>
> > On Oct 8, 2017, at 4:42 PM, David Adams via 4D_Tech <
> 4d_tech@lists.4d.com> wrote:
> >
> > What I'm concerned about is that CLOSE DOCUMENT may be
> > returning without the file *actually* being closed. That's really
> > problematic.
>
>
> I understand your thinking that 4D may not the way to go for event
> logging, but your concern about CLOSE DOCUMENT is where we do not agree.
> I'am sure you have seen CLOSE DOCUMENT fail, but I suspect that what you
> are seeing is not an issue with CLOSE DOCUMENT, but something else not
> readily apparent. I think you said at some point that 4D has recognized
> this as a bug, but I still question whether in fact it is.
>
> Perhaps you can show me in the sample database how to make CLOSE DOCUMENT
> fail or have another database that demonstrates the problem?
>
> When I saw your initial post in this regard, I jumped in because I do a
> lot of work that involves the opening and closing of documents. If a
> problem exists I really need to know about it. Thus far my testing based on
> your posts has not demonstrated anything that has caused me to doubt that
> CLOSE DOCUMENT will in fact close a file.
>
> John
>
>
> John Baughman
> Kailua, Hawaii
> (808) 262-0328
> john...@hawaii.rr.com
>
>
> **
> 4D Internet Users Group (4D iNUG)
> FAQ:  http://lists.4d.com/faqnug.html
> Archive:  http://lists.4d.com/archives.html
> Options: http://lists.4d.com/mailman/options/4d_tech
> Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
> **
>
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Hey John, thanks for the great post and all the work.

There's no reason for other people to know this, but John and I have
*totally* different coding styles. So I was really pleased he went through
my example and reworked it in his own way. That he turned up some problems
is instructive because he, for sure, approaches things form a different
angle than me.

> Open/Close Document: I think we all agree, even David, that it is now and
has always been our responsibility to close
> documents as quickly as possible after opening them.

Sorry I gave the impression at some point I ever thought otherwise. I now
and always believe that we're responsible for closing our own files. That's
not a question. What I'm concerned about is that CLOSE DOCUMENT may be
returning without the file *actually* being closed. That's really
problematic.

>  Worker processes in 4D are ready for prime time.

I suspect that this is true for many uses of workers. For UI stuff, they
seem like they'll be able to keep up with what even a complex UI in 4D can
push at it. And workers and CALL FORM are *massively* better than any
previous native solution. All of that stuff with SET PROCESS VARIABLE or
shared arrays with semaphores was just terrible - real garbage. I've said
that for years, so I was quite excited about the new features.

On the other hand, I was looking forward to taking a standard high-volume
task and leverage 4D's preemptive processing ability. John came up with a
solution, but it involves Semaphores and quite a bit of infrastructure that
either makes preemptive unavailable, or so expensive to get that it's
pointless.

For reliability, I'm going to look at sending the logs from NGNIX and cut
4D out of the process entirely.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Add,

Thanks a lot for chiming in! It's always good to hear from you guys in the
US office.

I'm not sure what problem your solution is solving. I'm not trying to be
flip, I just want to make sure to focus on the meat of the issue. A really
common approach to log writing is as follows:

Have one process manage the log disk file. So. when that thread starts, it
opens the file, keeps it open, writes to it and can then close it neatly.
You can then have any number of other processes message the "writer" to
stream information to the disk file. Lots of OS-level files, Web servers,
etc. follow this model. Why? Because it is *substantially* faster and
easier than anything else. You completely sidestep race conditions on the
file lock - there's no chance of a race condition because only one process
*ever* opens the file. It's a nice, tidy solution.

That's what I wanted to do with 4D's worker when I first saw them - I
assumed that would be pretty much anyone's impression because it's such a
classic use for a message+worker setup. I was excited because with a
preemptive worker, you could push all of this low-value logging over onto a
secondary core. It's a satisfyingly complete, tidy, and naturally
low-conflict, high-performance solution. That doesn't work in 4D.

Unfortunately, this doesn't seem to work. I can easily generate race
conditions from opening and close the file and restarting the worker. This
should be *impossible*. Something is wrong in how 4D is managing file
locks. I don't know what. I start a worker, open a file, write to it, close
the file, kill the worker. The file should be closed. Period. Usually it
is, sometimes it isn't. I have no explanation for this, but it definitively
blows up any plan to use workers for logging via a preemptive process.

John Baughman in his tests thinks that the problem is flooding the worker
and blowing up 4D's via memory exception. Could be. I briefly did a bit of
load testing like that, but not a lot.

So, either way, it doesn't look like 4D's CALL WORKER and worker system is
designed to scale or work safely/reliably under heavy load. I've come to
suspect that it was never intended for such tasks.The lack of a pause
mechanism or a way to count 'queued' entries are telling. They're very
standard (universal) features of a queuing/messaging system, but 4D doesn't
have them or seem to appreciate why you would need them. I've got feature
requests in for this stuff from months ago. Note that if you do any kind of
heavy load, you need to be able to measure the state of a queue to see if
you need to spin up another one. That 4D lacks this feature (or seemingly
interest in such a feature) suggests that I'm off-base to even consider 4D
workers for heavy loads. Just not built for it.

4D never said that their workers were meant for heavy lifting. I think that
they were designed to handle various kinds of UI-related tasks in 4D. I
haven't got much interest in that (I did a bit of a publish-subscribe
system that I showed at 4DMETHOD, that was fun to work through), and I'll
guess that CALL WORKER and CALL FORM are just fine for that.

But for what I need? I have to conclude that 4D isn't the right tool
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

I was never focused on LOG EVENT (?) I've never used the command and would
prefer not to in this case. I only brought it up because it would
potentially well with Loggly. (I'm not committed to Loggy and may not stick
with that platform, for what that's worth. But it's worth trying for now.)

I have no access to the forums, so I don't know what your link says. But if
the title is safe to go by then, yes, that might help. I'll have to test it
out to see how well it works before I know. In theory, what I was trying to
do in the first place is a completely safe idea - even better than LEP. But
it isn't safe in practice.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Keisuke Miyako via 4D_Tech]

LAUNCH EXTERNAL PROCESS becomes thread safe in 16R5

http://forums.4d.com/Post/FR/21049933/1/21050200#21050200

which opens many possibilities, the logger command on Mac, for example.

perhaps we need not focus on LOG EVENT anymore...




**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

I've posted about my various worker log problems here and on some other
threads and even posted my sample database for review. Lately, John
Baughman has really been sinking his teeth into this issue and has spent a
*ton* of time working on it. Thank you John! The news is bad, but I figured
I'd post it here as part of this thread. I won't say a lot, but John might
want to explain his point of view. He's an optimistic person, with a
cheerful nature and he likes people. Despite that, I still like him ;-)

Anyway, John took a copy of the sample database (including the correction
contributed by David Porter) and tried to figure out what he could. My
summary:

* John is able to crash 4D just by flooding the queue.

* He came up with some ideas to help manage the situation, but they
involved either or semaphores or IP variables.

* John also came to see (very quickly) that you need a function to report
current queue size.

Now, it's entirely possible that 4D never intended their CALL WORKER system
to be used in a high-transaction setting. They have offered no guidance on
the systems limitations and scope. I briefly tried crashing it with a
message flood months back and thought that 4D preformed well. In fact, I
was looking to see if it created disk scratch files, but I couldn't find
any. John sounds like he's able to flood and crash the system pretty
reliably, but not every time.

One of my primary goals in using CALL WORKER was to avoid writing records
and take some work off of core 1. There appears to be no safe and reliable
way to meet those goals. This is a total bummer as even my HTTP push
solution won't be safe.

My next good idea is to see about pushing as much of the logging as I can
onto NGNIX which will absolutely, definitely have zero problems with
whatever we can throw at it.

John my have more to say, but I think I'm likely done with this subject.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Related wrinkleI'm now wondering about something else: Does KILL WORKER
completely kill a worker, or does it sometimes just hurt it really, really
badly? I have been working under the assumption that when KILL WORKER
completes, that the worker is *totally* gone. Meaning, no process-level
values (variables, etc.) remain anywhere.A worker can be restarted very
quickly after being killed. It gets the same name (workers have unique,
case-sensitive names, outside of buggy situations) - but the contents
should be blank. At least, that's what I think and what would be best. Web
processes, as an example, do *not* work like this - they stay alive for a
few seconds and may get reused. New process *does* work like this. Let a
process finish and restart a fresh version and you get a blank slate.

I suspect with workers that they normally die completely when killed, but
not always.

I've just reread the docs and they don't address this point explicitly.
This is the sort of question I tried using the Forums to get answered and,
frankly, I didn't get answers. So, I'm going to have to go with the
assumption that a new worker *may not be virginal.* There may be some gunk
hanging around form an earlier incarnation of the worker. This is only
relevant if you use KILL WORKER, but that's a standard command.

Does anyone know anything more about this that could help change some of my
speculations into information, one wary or another?
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Hey, David Porter spotted a bug in my code and I wanted to push this part
of the thread up to the list for the archives, etc.:

On Tue, Sep 26, 2017 at 5:05 PM, David Porter  wrote:

> Thanks for posting the LogWorker code, it has been fun experimenting with
it.
>
> I have been testing only the preemptive test code.
> Running on a Mac Pro (Late 2013) with 6-Core Intel Xeon E5 , Mac OS X
10.12.6
> 4D 16.1 hotfix 2 , 64 bit app.  ( Not server )
>
> Yes, there is a bug in the code.
> Method: LogWorker_Kill ,need to add the line
> Log_Path:=“” // This is required to get the LogWorker_Start code to open
the log again
>
> Even so, your code would crash interpreted before the Kill was ever sent.
> Putting in delay process in LogWorker_CallABunch_Preemptive, would get it
to run interpreted.
> So, clearly there is a 4D bug here.
>
> Compiled, I am able to remove all the delay processes, and run it to
completion.
> I do get some runtime errors about broken communication.
> Again, I can make them go away with some delay processes, something I was
trying to avoid.
>
> So, I encourage you to take another look at this code.
>

My first reply, before checking the code based on what David said:

Hey! Thanks for checking the code, you're awesome!

Thanks for the bug catch on my code. I'm sure that wasn't from me. Darn
kids, getting into my code and messing things up

How long did you have to delay process compiled to get it to work? I tried
up to 3 seconds and it still didn't work. In theory (as I understand it),
DELAY PROCESS should *not* be needed. Meanin, CLOSE DOCUMENT should not
return until the document is actually closed. I think I even tried it with
SET CHANNEL and found the same problem, but don't quote me on that.

If my understanding about the synchronous nature of the file/channel
commands is correct, and a process delay is needed, it points to an
underlying problem that would leave me not trusting the solution. Even if
it only shows up after a few hours/days/weeks...that's not good enough :(


My second reply now:
Okay, I've gone back and updated the code, just as David described. That
fix makes the system *way* better. Unfortunately, even with that fix and
the 3 second delay, the problem still crops up. It takes longer, but it's
still there. I guess it's an (un)happy coincidence that my bug amplified an
underlying bug in 4D. For a logging situation, a race condition rate of
1:1,000,000 isn't even close to good enough. It needs to be zero. Always.
In this case, i was able to provoke the bug in a few minutes :( I'm told
that 4D has accepted my report but Partners in Aus don't have direct access
to the bug system. And I've never heard anything from France so I don't
have a bug report number or anything else to do on.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Hey Tim,

> Consider the situation where you have a mission critical system that is
up 24/7 and you need logging to always work every second of the day.

> How do you handle the situation where the stand-alone log writer app
crashes, is not running due to a machine restart, or for whatever reason
>  goes deaf and stops responding to the HTTP calls?  You certainly don’t
want any possibility of losing some logging information.

Again, talking about a workaround. I want to log to disk out of 4D via SEND
PACKET.

As to your point, it's true. However, I'm seeing is a *far* more likely
that 4D Server crashes than a 4D stand-alone. But your point is good.
Perhaps it's better to find a small, stable service (Windows) that can run
in the background to handle the HTTP-push-to-disk task and leave 4D out of
it entirely.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Keisuke,

Thanks for the background information on LOG EVENT, your details are
*always* interesting. In my case, I don't think that it has anything to do
with what I'm dealing with. I'm not talking about 4D events or 4D logs, I'm
talking about custom logs with data I'm sending out. LOG EVENT isn't my
first choice, it isn't even my secondbut my first and second choices
aren't doable because of this fatal bug in 4D.

On Tue, Sep 26, 2017 at 4:26 PM, Keisuke Miyako via 4D_Tech <
4d_tech@lists.4d.com> wrote:

> sometimes you will see a kind of "comment" line in the request log,
> in particular "TTF" or time to forget,
> which describes a change of state in the process:
>
> a: automatic relation
> b: record stack
> c: current record
> d: current selection
> e: transaction
>
> these are not real "requests",
> in that the information is not sent by itself.
> rather, it has an impact on future requests.
>
> "INFO" is a pseudo module name
> (as opposed to srv4, cli4, dbmg, etc.)
>  for writing such entries in the request log.
>
> in v2004, 4D was cooperative,
> so you could trust that the logs are recorded sequentially.
>
> however, since v11,
> a different process could write interject between "srv4" and "INFO", for
> example,
> so you can not assume that the two subsequent lines make a pair.
>
> "process info index" and "task id" is used to link such lines.
>
> it's in the documentation.
>
> http://doc.4d.com/4Dv16/4D/16.1/Appendix-E-Description-of-
> log-files.300-3373556.en.html
>
> > 2017/09/26 23:07、David Adams via 4D_Tech <4d_tech@lists.4d.com> のメール：
> > Not sure which ID that is
>
>
>
>
> **
> 4D Internet Users Group (4D iNUG)
> FAQ:  http://lists.4d.com/faqnug.html
> Archive:  http://lists.4d.com/archives.html
> Options: http://lists.4d.com/mailman/options/4d_tech
> Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
> **
>
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Tim Nevels via 4D_Tech]

On Sep 26, 2017, at 9:08 AM, David Adams wrote:

>> As stupid as it sounds, another option is to push the log entries to
>> something else locally - even a stand-alone built 4D app - and let it write
>> the disk files.
>> Then you could use a service with a custom agent, like SumoLogic or
>> Splunk. Actually, that's not a terrible idea at all...who cares if that
>> data file gets bloaty?
>> Clear it out, throw it out, start a new one.
> 
> Now I'm loving this idea. Do a special build to generate a stand-alone log
> writer app and message it with HTTP. This tool is functioning as a logging
> "agent." There are a lot of advantages to this approach in some
> environments:

Consider the situation where you have a mission critical system that is up 24/7 
and you need logging to always work every second of the day. 

How do you handle the situation where the stand-alone log writer app crashes, 
is not running due to a machine restart, or for whatever reason goes deaf and 
stops responding to the HTTP calls?  You certainly don’t want any possibility 
of losing some logging information.

Tim


Tim Nevels
Innovative Solutions
785-749-3444
timnev...@mac.com


**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Porter via 4D_Tech]

David,

Thanks for posting the LogWorker code, it has been fun experimenting with it.

I have been testing only the preemptive test code.
Running on a Mac Pro (Late 2013) with 6-Core Intel Xeon E5 , Mac OS X 10.12.6
4D 16.1 hotfix 2 , 64 bit app.  ( Not server )

Yes, there is a bug in the code.
Method: LogWorker_Kill ,need to add the line
Log_Path:=“” // This is required to get the LogWorker_Start code to open the 
log again

Even so, your code would crash interpreted before the Kill was ever sent.
Putting in delay process in LogWorker_CallABunch_Preemptive, would get it to 
run interpreted.
So, clearly there is a 4D bug here.

Compiled, I am able to remove all the delay processes, and run it to completion.
I do get some runtime errors about broken communication.
Again, I can make them go away with some delay processes, something I was 
trying to avoid.

So, I encourage you to take another look at this code.

Dave Porter
Tailored Solutions, Inc.
Business Management Software for Label Converters
http://www.labeltraxx.com/

> On Sep 25, 2017, at 7:57 AM, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
> wrote:
> 
> On Mon, Sep 25, 2017 at 12:04 PM, Epperlein, Lutz (agendo) via 4D_Tech <
> 4d_tech@lists.4d.com> wrote:
> I asked because we use a little own implementation of writing log files.
> This is all before V16. We use semaphores to avoid race conditions while
> writing to the file.
> And one of our first projects after updating to V16 should be the rewriting
> of this code using workers. So I'm a bit disappointed to hear that.
> 
> Yes, centralizing a log writer seems like the most obvious use of a worker,
> so I also was disappointed. But perhaps I'm wrong? It would not be the
> first time that I've done something stupid. Just in case I'm missing
> something obvious, I've posted a copy of the test database I've used to
> demonstrate the bug here:
> 
> http://www.4dcompanion.com/LogWorker.zip
> 
> It's a crude test database. What I was doing is compiling it and running
> LogWorker_CallABunch_Coop or LogWorker_Test_Preemptive.
> 
> The test isn't to see if you can use CALL WORKER to execute code that
> passes a log entry to a worker.
> You can.
> 
> The test isn't to see if you can then keep the log file open just in the
> worker to avoid contention on the file.
> You can.
> 
> The test is to see what happens when you need to "roll" the log. Namely,
> close the current log, rename it and open a new log.
> This is where things go sideways.
> 
> If I remember correctly, I've retested this as far as 16.2 and R3 but not
> R4. Perhaps a fresh set of eyes would help here. I do see that I tried
> putting in a 3 second delay when rolling the log in case that gave 4D
> and/or the OS a chance to catch up. Didn't help.
> 
> So, if I'm doing something foolish and wrong *please* tell me. I hate being
> wrong, but I'd also rather know when I'm wrong. So, yeah, let me know. If
> there's another way to approach this that's reliable, also please say. If
> that way requires semaphores then, well, nothat kind of defeats the
> whole purpose. At that point, I'd use non-preemptive code with NTK IPC
> channels. That's been working flawlessly for years.
> 
> One thing: Any solution has to be 100% reliable. For server-side code like
> this, a success rate of 99.9% isn't even close. When an error can bring the
> server down, it's a non-starter. Particularly an error that's super easy to
> generate.
> 
> The truth is that I'd really like to use disk files for logs. They're
> simple, lightweight, cheap and robust. You can feed them into your
> aggregator of choice in a million different ways, they take up no room in
> the database, you can resume posting of entries after a crash, they're just
> a solid choice. Hence, their near-universal popularity.
> 
> P.S. I know that using CALL WORKER inevitably means some log entries will
> be lost during restart. That's an acceptable cost in this particular case.
> Crashing/freezing the server is not.
> **
> 4D Internet Users Group (4D iNUG)
> FAQ:  http://lists.4d.com/faqnug.html
> Archive:  http://lists.4d.com/archives.html
> Options: http://lists.4d.com/mailman/options/4d_tech
> Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
> **

**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Keisuke Miyako via 4D_Tech]

sometimes you will see a kind of "comment" line in the request log,
in particular "TTF" or time to forget,
which describes a change of state in the process:

a: automatic relation
b: record stack
c: current record
d: current selection
e: transaction

these are not real "requests",
in that the information is not sent by itself.
rather, it has an impact on future requests.

"INFO" is a pseudo module name
(as opposed to srv4, cli4, dbmg, etc.)
 for writing such entries in the request log.

in v2004, 4D was cooperative,
so you could trust that the logs are recorded sequentially.

however, since v11,
a different process could write interject between "srv4" and "INFO", for 
example,
so you can not assume that the two subsequent lines make a pair.

"process info index" and "task id" is used to link such lines.

it's in the documentation.

http://doc.4d.com/4Dv16/4D/16.1/Appendix-E-Description-of-log-files.300-3373556.en.html

> 2017/09/26 23:07、David Adams via 4D_Tech <4d_tech@lists.4d.com> のメール：
> Not sure which ID that is




**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

Chip's right about server-side code not needing network bandwidth. I was
jumbling a few of my stories unclearly. Yes, we're starting with
server-side only process getting logged, but that will change. Once you
want to keep error, access, and event logs and tie them together, it's nice
to be able to log from the client side as well. I'm planning ahead a bit
here.

> doesn't have to be that way; you can have a local external database on
the client side.

If I'm going to use an external database, it's going to be Postgres. 4D has
given every appearance of abandoning further work on their SQL "support",
so I'm not going to base any designs on what amounts to a dead-end feature.
Sorry :( I liked the idea of SQL in 4D and loved the idea of external
database. But, for what it's worth, they're no usable from preemptive
processes anyway, so...

> but I am slightly puzzled how LOG EVENT is in the spotlight.

I brought it up because that's one way to get events to Loggly. Loggly
describes itself as an "agentless" service. Which just means "we use system
agents and don't provide our own." So, LOG EVENT should work. File that
under "commands I've never used". So I wasn't even clear if it was a sane
idea to ask for a preemptive-safe version. Seems like it should be. If it
isn't, I'll just put that idea out of my mind forever.

> preemptively logging can make things more complicated,

My basic design with a preemptive worker collecting log events in memory
centrally and pushing them out to a disk file is *entirely* normal. This is
what high-volume Web servers do. Probably anyone that's done a lot of
working thought of the same design *instantly* when they heard about CALL
WORKER. It's just that obvious. The only reason I can't do this is because
of a *crashing server bug* in 4D. As far as I can tell. So, good design,
proven design, sensible design...doesn't work. Doesn't workwith extreme
prejudice.

> a new ID was introduced because preemptive multi-line logs can be
interwoven.
Not sure which ID that is, but I'm planning on using the unique ID from
PROCESS PROPERTIES and a unified timeline to tie together events from
different logs related to the same process.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Keisuke Miyako via 4D_Tech]

well, Begin SQL/End SQL is not thread safe either so that's not going to help.

but back to the original point:

LOG EVENT has many modes, is there a particular type of log that you wish were 
thread safe?

because, technically, you could just call a command with arguments and that 
would be recorded in the debug log without the use of a LOG EVENT...

2017/09/26 21:27、Keisuke Miyako via 4D_Tech 
<4d_tech@lists.4d.com> のメール：
doesn't have to be that way; you can have a local external database on the 
client side.
http://doc.4d.com/4Dv15/4D/15/USE-DATABASE.300-2288124.en.html



**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Keisuke Miyako via 4D_Tech]

doesn't have to be that way; you can have a local external database on the 
client side.
http://doc.4d.com/4Dv15/4D/15/USE-DATABASE.300-2288124.en.html

but I am slightly puzzled how LOG EVENT is in the spotlight.
preemptively logging can make things more complicated,
look at 4DRequestsLog.txt / 4DRequestsLog_ProcessInfo.txt.
a new ID was introduced because preemptive multi-line logs can be interwoven.
it wasn't necessary back in days when 4D was all cooperative.

http://doc.4d.com/4Dv16/4D/16.1/Appendix-E-Description-of-log-files.300-3373556.en.html

> 2017/09/26 20:41、Chip Scheide via 4D_Tech <4d_tech@lists.4d.com> のメール：
> so, if this is a logging issue, will not most/all events requiring logging 
> pass through the server?
> so logging would not/should not take network bandwidth -
> log from trigger, log from stored methods, log from 'execute on server'




**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Chip Scheide via 4D_Tech]

so, if this is a logging issue, will not most/all events requiring logging pass 
through the server?
so logging would not/should not take network bandwidth -
log from trigger, log from stored methods, log from 'execute on server'

>> 
>> 
>> Thanks for the explanation. Your second point (no reason to have the data
>> in 4D) strikes me as more theological than practical,
> 
> 
> Depends on your situation. I nearly killed a system once from pushing the
> logging data over the network. Not philosophical, existential in the
> contemporary sense of "life and death threat." So, that happened. But in a
> small system? Everything is easier in a small system. So, yeah, unless
> you're going to have tons of data in the logs and they're very busy, I'd
> say that it's a matter of taste.

Hell is other people 
 Jean-Paul Sartre
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

On Tue, Sep 26, 2017 at 10:38 AM, Jeremy Roussak via 4D_Tech <
4d_tech@lists.4d.com> wrote:

> David,
>
> Thanks for the explanation. Your second point (no reason to have the data
> in 4D) strikes me as more theological than practical,


Depends on your situation. I nearly killed a system once from pushing the
logging data over the network. Not philosophical, existential in the
contemporary sense of "life and death threat." So, that happened. But in a
small system? Everything is easier in a small system. So, yeah, unless
you're going to have tons of data in the logs and they're very busy, I'd
say that it's a matter of taste.


> but the rest are certainly excellent reasons. I wasn’t aware that 4D
> didn’t cope well with thrashing tables, so that’s something I’ll bear in
> mind in future.
>

Well, that's been my experience, perhaps things have changed? I usually
mange to slip out of the back of the room when they're asking for
volunteers to do server admin. Many years of suffering...don't like server
admin.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Jeremy Roussak via 4D_Tech]

David,

Thanks for the explanation. Your second point (no reason to have the data in 
4D) strikes me as more theological than practical, but the rest are certainly 
excellent reasons. I wasn’t aware that 4D didn’t cope well with thrashing 
tables, so that’s something I’ll bear in mind in future.

Live and learn.

Jeremy


Jeremy Roussak
j...@mac.com



> On 25 Sep 2017, at 19:03, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
> wrote:
> 
> On Mon, Sep 25, 2017 at 6:06 PM, Jeremy Roussak via 4D_Tech <
> 4d_tech@lists.4d.com> wrote:
> 
>> Please forgive me if I’m being dim, but isn’t a solution (maybe not the
>> best, but a solution) to maintain the log as records in a table, which is
>> periodically emptied into a file by a process which opens, writes and
>> closes that file, then deletes the records in the table?
>> 
>> It’s not an approach which I’ve tried, and you may have good reasons for
>> rejecting it. I’m just curious to know what they are.
>> 
>> 
> Jeremy,
> 
> Using a 4D table as a sort of cache for log lines is a perfectly sensible
> idea, but also one I'd like to avoid. I did this some years back in a very
> high-volume system and ended up killing a lot of performance as a
> consequence. (Just ask Justin Leavens.) Now, you could take steps to reduce
> the network activity involved, to be sure, but there are still a few points
> that come to mind:
> 
> * 4D doesn't do well (or at least hasn't historically done well) with
> tables that get thrashed a lot. Add-delete-add-delete. Gets really slow and
> horrible. So then you have to do compacts, or hijinks with reusing records,
> or all kinds of special magic with never deleting records. Life is too
> short for any of that, if at all avoidable.
> 
> * There's no _real_ reason to have the data in 4D at any point. 4D isn't an
> analysis platform and it isn't something that I'd use for
> high-volume/low-data-content material like log entries. So, there's no good
> reason for it to be in 4D other than as a cache. I would consider using a
> small table as a cache for storing lines that didn't upload/output to a log
> file, but only if the % of failure was pretty low.
> 
> * With a post-to-table-log-and-clear system, you now need a process to poll
> the table. You can do this in a way that is relatively inexpensive, but
> it's not free.
> 
> * Potentially lots of network traffic for zero gain.
> 
> But there are tons of ways to think about this sort of thing, and lots of
> different setups and requirements. My judgment calls and current
> constraints are likely different to what other people are dealing with. So,
> there are plenty of good arguments for any particular design. I'm just
> trying to be clear that while I'm not keen on the approach you suggest in
> this case, it's not because I think it's inherently bad - I've used it
> before. It's just that in this case I don't want the log data in 4D, if at
> all possible. I see that as pure cost with no gain.
> 
> Hopefully, someone will find something silly in what I'm doing as the CALL
> WORKER idea is really ver nice. You have n processes doing their thing -
> running code, serving Web requests, handling windows, etc. Then they can
> send log data (events, behaviors, errors, etc.) over to a central log
> worker. Using CALL WORKER, this is quite fast. (4D can stack up tons of
> these little requests quite well.) From there, you've got one process
> handling all of the log data. A single external file for a particular log
> is perfect at this point. It's fast and super easy to use. The whole point
> of using a single process for this is to avoid contention on the file
> amongst processes. That can otherwise be a *huge* and totally unworthy
> bottleneck. So, one process for logging which has the file open in
> read-write all the time. So good. Such a standard design. Simple, clean,
> cheap, efficient...doesn't work in 4D. Unless there's a bug in my bug
> report ;-)
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

> As stupid as it sounds, another option is to push the log entries to
something else locally - even a stand-alone built 4D app - and let it write
the disk files.
>  Then you could use a service with a custom agent, like SumoLogic or
Splunk. Actually, that's not a terrible idea at all...who cares if that
data file gets bloaty?
>  Clear it out, throw it out, start a new one.

Now I'm loving this idea. Do a special build to generate a stand-alone log
writer app and message it with HTTP. This tool is functioning as a logging
"agent." There are a lot of advantages to this approach in some
environments:

* You can put it on the same machine as the server(s), or not.

* You can send in all sorts of different logging data.

* You can do something smart with the data, like aggregates, if you want
to. (I don't want to, but someone else might like to do that.)

* You completely divide up stashing something in the log "send it to the
log writer" from what happens next. Want to change formats? Services?
Transport mechanisms? It's all right there. So, you could use disk files
one day and switch to HTTP upload the next...or pushing it into Postgres,
or whatever.

* Since the target app is a stand-alone, it can run preemptive processes.
Nice when you're generating log data on 4D Remote which _cannot_ run
preemptive processes.

Yeah, I think this has gone from Plan B to Plan A.

On Tue, Sep 26, 2017 at 8:28 AM, David Adams  wrote:

> > Not having my server crash sounds like a very good reason to use records.
> > At least until a better solution comes along.
>
> Plan B in this case is to push the data to Loggly via HTTP.
>
> As stupid as it sounds, another option is to push the log entries to
> something else locally - even a stand-alone built 4D app - and let it write
> the disk files. Then you could use a service with a custom agent, like
> SumoLogic or Splunk. Actually, that's not a terrible idea at all...who
> cares if that data file gets bloaty? Clear it out, throw it out, start a
> new one.
>
>
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

> At least until a better solution comes along.

I have zero reason to assume that this bug will ever be fixed.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

> Not having my server crash sounds like a very good reason to use records.
> At least until a better solution comes along.

Plan B in this case is to push the data to Loggly via HTTP.

As stupid as it sounds, another option is to push the log entries to
something else locally - even a stand-alone built 4D app - and let it write
the disk files. Then you could use a service with a custom agent, like
SumoLogic or Splunk. Actually, that's not a terrible idea at all...who
cares if that data file gets bloaty? Clear it out, throw it out, start a
new one.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Doug Hall via 4D_Tech]

Not having my server crash sounds like a very good reason to use records.
At least until a better solution comes along.

My 2¢

On Mon, Sep 25, 2017 at 1:03 PM, David Adams via 4D_Tech <
4d_tech@lists.4d.com> wrote:

> On Mon, Sep 25, 2017 at 6:06 PM, Jeremy Roussak via 4D_Tech <
> 4d_tech@lists.4d.com> wrote:
>
> > Please forgive me if I’m being dim, but isn’t a solution (maybe not the
> > best, but a solution) to maintain the log as records in a table, which is
> > periodically emptied into a file by a process which opens, writes and
> > closes that file, then deletes the records in the table?
> >
> > It’s not an approach which I’ve tried, and you may have good reasons for
> > rejecting it. I’m just curious to know what they are.
> >
> >
> Jeremy,
>
> Using a 4D table as a sort of cache for log lines is a perfectly sensible
> idea, but also one I'd like to avoid. I did this some years back in a very
> high-volume system and ended up killing a lot of performance as a
> consequence. (Just ask Justin Leavens.) Now, you could take steps to reduce
> the network activity involved, to be sure, but there are still a few points
> that come to mind:
>
> * 4D doesn't do well (or at least hasn't historically done well) with
> tables that get thrashed a lot. Add-delete-add-delete. Gets really slow and
> horrible. So then you have to do compacts, or hijinks with reusing records,
> or all kinds of special magic with never deleting records. Life is too
> short for any of that, if at all avoidable.
>
> * There's no _real_ reason to have the data in 4D at any point. 4D isn't an
> analysis platform and it isn't something that I'd use for
> high-volume/low-data-content material like log entries. So, there's no good
> reason for it to be in 4D other than as a cache. I would consider using a
> small table as a cache for storing lines that didn't upload/output to a log
> file, but only if the % of failure was pretty low.
>
> * With a post-to-table-log-and-clear system, you now need a process to poll
> the table. You can do this in a way that is relatively inexpensive, but
> it's not free.
>
> * Potentially lots of network traffic for zero gain.
>
> But there are tons of ways to think about this sort of thing, and lots of
> different setups and requirements. My judgment calls and current
> constraints are likely different to what other people are dealing with. So,
> there are plenty of good arguments for any particular design. I'm just
> trying to be clear that while I'm not keen on the approach you suggest in
> this case, it's not because I think it's inherently bad - I've used it
> before. It's just that in this case I don't want the log data in 4D, if at
> all possible. I see that as pure cost with no gain.
>
> Hopefully, someone will find something silly in what I'm doing as the CALL
> WORKER idea is really ver nice. You have n processes doing their thing -
> running code, serving Web requests, handling windows, etc. Then they can
> send log data (events, behaviors, errors, etc.) over to a central log
> worker. Using CALL WORKER, this is quite fast. (4D can stack up tons of
> these little requests quite well.) From there, you've got one process
> handling all of the log data. A single external file for a particular log
> is perfect at this point. It's fast and super easy to use. The whole point
> of using a single process for this is to avoid contention on the file
> amongst processes. That can otherwise be a *huge* and totally unworthy
> bottleneck. So, one process for logging which has the file open in
> read-write all the time. So good. Such a standard design. Simple, clean,
> cheap, efficient...doesn't work in 4D. Unless there's a bug in my bug
> report ;-)
> **
> 4D Internet Users Group (4D iNUG)
> FAQ:  http://lists.4d.com/faqnug.html
> Archive:  http://lists.4d.com/archives.html
> Options: http://lists.4d.com/mailman/options/4d_tech
> Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
> **
>
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

On Mon, Sep 25, 2017 at 6:06 PM, Jeremy Roussak via 4D_Tech <
4d_tech@lists.4d.com> wrote:

> Please forgive me if I’m being dim, but isn’t a solution (maybe not the
> best, but a solution) to maintain the log as records in a table, which is
> periodically emptied into a file by a process which opens, writes and
> closes that file, then deletes the records in the table?
>
> It’s not an approach which I’ve tried, and you may have good reasons for
> rejecting it. I’m just curious to know what they are.
>
>
Jeremy,

Using a 4D table as a sort of cache for log lines is a perfectly sensible
idea, but also one I'd like to avoid. I did this some years back in a very
high-volume system and ended up killing a lot of performance as a
consequence. (Just ask Justin Leavens.) Now, you could take steps to reduce
the network activity involved, to be sure, but there are still a few points
that come to mind:

* 4D doesn't do well (or at least hasn't historically done well) with
tables that get thrashed a lot. Add-delete-add-delete. Gets really slow and
horrible. So then you have to do compacts, or hijinks with reusing records,
or all kinds of special magic with never deleting records. Life is too
short for any of that, if at all avoidable.

* There's no _real_ reason to have the data in 4D at any point. 4D isn't an
analysis platform and it isn't something that I'd use for
high-volume/low-data-content material like log entries. So, there's no good
reason for it to be in 4D other than as a cache. I would consider using a
small table as a cache for storing lines that didn't upload/output to a log
file, but only if the % of failure was pretty low.

* With a post-to-table-log-and-clear system, you now need a process to poll
the table. You can do this in a way that is relatively inexpensive, but
it's not free.

* Potentially lots of network traffic for zero gain.

But there are tons of ways to think about this sort of thing, and lots of
different setups and requirements. My judgment calls and current
constraints are likely different to what other people are dealing with. So,
there are plenty of good arguments for any particular design. I'm just
trying to be clear that while I'm not keen on the approach you suggest in
this case, it's not because I think it's inherently bad - I've used it
before. It's just that in this case I don't want the log data in 4D, if at
all possible. I see that as pure cost with no gain.

Hopefully, someone will find something silly in what I'm doing as the CALL
WORKER idea is really ver nice. You have n processes doing their thing -
running code, serving Web requests, handling windows, etc. Then they can
send log data (events, behaviors, errors, etc.) over to a central log
worker. Using CALL WORKER, this is quite fast. (4D can stack up tons of
these little requests quite well.) From there, you've got one process
handling all of the log data. A single external file for a particular log
is perfect at this point. It's fast and super easy to use. The whole point
of using a single process for this is to avoid contention on the file
amongst processes. That can otherwise be a *huge* and totally unworthy
bottleneck. So, one process for logging which has the file open in
read-write all the time. So good. Such a standard design. Simple, clean,
cheap, efficient...doesn't work in 4D. Unless there's a bug in my bug
report ;-)
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[Jeremy Roussak via 4D_Tech]

Please forgive me if I’m being dim, but isn’t a solution (maybe not the best, 
but a solution) to maintain the log as records in a table, which is 
periodically emptied into a file by a process which opens, writes and closes 
that file, then deletes the records in the table?

It’s not an approach which I’ve tried, and you may have good reasons for 
rejecting it. I’m just curious to know what they are.

Jeremy

Jeremy Roussak
j...@mac.com



> On 25 Sep 2017, at 13:57, David Adams via 4D_Tech <4d_tech@lists.4d.com> 
> wrote:
> 
> On Mon, Sep 25, 2017 at 12:04 PM, Epperlein, Lutz (agendo) via 4D_Tech <
> 4d_tech@lists.4d.com> wrote:
> I asked because we use a little own implementation of writing log files.
> This is all before V16. We use semaphores to avoid race conditions while
> writing to the file.
> And one of our first projects after updating to V16 should be the rewriting
> of this code using workers. So I'm a bit disappointed to hear that.
> 
> Yes, centralizing a log writer seems like the most obvious use of a worker,
> so I also was disappointed. But perhaps I'm wrong? It would not be the
> first time that I've done something stupid. Just in case I'm missing
> something obvious, I've posted a copy of the test database I've used to
> demonstrate the bug here:
> 
> http://www.4dcompanion.com/LogWorker.zip
> 
> It's a crude test database. What I was doing is compiling it and running
> LogWorker_CallABunch_Coop or LogWorker_Test_Preemptive.
> 
> The test isn't to see if you can use CALL WORKER to execute code that
> passes a log entry to a worker.
> You can.
> 
> The test isn't to see if you can then keep the log file open just in the
> worker to avoid contention on the file.
> You can.
> 
> The test is to see what happens when you need to "roll" the log. Namely,
> close the current log, rename it and open a new log.
> This is where things go sideways.
> 
> If I remember correctly, I've retested this as far as 16.2 and R3 but not
> R4. Perhaps a fresh set of eyes would help here. I do see that I tried
> putting in a 3 second delay when rolling the log in case that gave 4D
> and/or the OS a chance to catch up. Didn't help.
> 
> So, if I'm doing something foolish and wrong *please* tell me. I hate being
> wrong, but I'd also rather know when I'm wrong. So, yeah, let me know. If
> there's another way to approach this that's reliable, also please say. If
> that way requires semaphores then, well, nothat kind of defeats the
> whole purpose. At that point, I'd use non-preemptive code with NTK IPC
> channels. That's been working flawlessly for years.
> 
> One thing: Any solution has to be 100% reliable. For server-side code like
> this, a success rate of 99.9% isn't even close. When an error can bring the
> server down, it's a non-starter. Particularly an error that's super easy to
> generate.
> 
> The truth is that I'd really like to use disk files for logs. They're
> simple, lightweight, cheap and robust. You can feed them into your
> aggregator of choice in a million different ways, they take up no room in
> the database, you can resume posting of entries after a crash, they're just
> a solid choice. Hence, their near-universal popularity.
> 
> P.S. I know that using CALL WORKER inevitably means some log entries will
> be lost during restart. That's an acceptable cost in this particular case.
> Crashing/freezing the server is not.
> **
> 4D Internet Users Group (4D iNUG)
> FAQ:  http://lists.4d.com/faqnug.html
> Archive:  http://lists.4d.com/archives.html
> Options: http://lists.4d.com/mailman/options/4d_tech
> Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
> **

**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

On Mon, Sep 25, 2017 at 12:04 PM, Epperlein, Lutz (agendo) via 4D_Tech <
4d_tech@lists.4d.com> wrote:
I asked because we use a little own implementation of writing log files.
This is all before V16. We use semaphores to avoid race conditions while
writing to the file.
And one of our first projects after updating to V16 should be the rewriting
of this code using workers. So I'm a bit disappointed to hear that.

Yes, centralizing a log writer seems like the most obvious use of a worker,
so I also was disappointed. But perhaps I'm wrong? It would not be the
first time that I've done something stupid. Just in case I'm missing
something obvious, I've posted a copy of the test database I've used to
demonstrate the bug here:

http://www.4dcompanion.com/LogWorker.zip

It's a crude test database. What I was doing is compiling it and running
LogWorker_CallABunch_Coop or LogWorker_Test_Preemptive.

The test isn't to see if you can use CALL WORKER to execute code that
passes a log entry to a worker.
You can.

The test isn't to see if you can then keep the log file open just in the
worker to avoid contention on the file.
You can.

The test is to see what happens when you need to "roll" the log. Namely,
close the current log, rename it and open a new log.
This is where things go sideways.

If I remember correctly, I've retested this as far as 16.2 and R3 but not
R4. Perhaps a fresh set of eyes would help here. I do see that I tried
putting in a 3 second delay when rolling the log in case that gave 4D
and/or the OS a chance to catch up. Didn't help.

So, if I'm doing something foolish and wrong *please* tell me. I hate being
wrong, but I'd also rather know when I'm wrong. So, yeah, let me know. If
there's another way to approach this that's reliable, also please say. If
that way requires semaphores then, well, nothat kind of defeats the
whole purpose. At that point, I'd use non-preemptive code with NTK IPC
channels. That's been working flawlessly for years.

One thing: Any solution has to be 100% reliable. For server-side code like
this, a success rate of 99.9% isn't even close. When an error can bring the
server down, it's a non-starter. Particularly an error that's super easy to
generate.

The truth is that I'd really like to use disk files for logs. They're
simple, lightweight, cheap and robust. You can feed them into your
aggregator of choice in a million different ways, they take up no room in
the database, you can resume posting of entries after a crash, they're just
a solid choice. Hence, their near-universal popularity.

P.S. I know that using CALL WORKER inevitably means some log entries will
be lost during restart. That's an acceptable cost in this particular case.
Crashing/freezing the server is not.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

RE: Making LOG EVENT thread-safe

[Epperlein, Lutz (agendo) via 4D_Tech]

I asked because we use a little own implementation of writing log files. This 
is all before V16. We use semaphores to avoid race conditions while writing to 
the file. 
And one of our first projects after updating to V16 should be the rewriting of 
this code using workers. So I'm a bit disappointed to hear that.

Regards
Lutz
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

Re: Making LOG EVENT thread-safe

[David Adams via 4D_Tech]

On Mon, Sep 25, 2017 at 10:43 AM, Epperlein, Lutz (agendo) <
lutz.epperl...@agendo.de> wrote:

> A question:
> What other approaches did you try to implement a logging feature using
> preemptive threads. I'm pretty sure there is something buried in the
> threads of this mailinglist but I'm not able to find it.
>
>
I would very likely have used files and an external collector...but this
didn't work out. Within 15 minutes of trying this, I discovered that it's
*very* easy to throw 4D into a fatal race condition when rolling log files.
(It's also possible in cooperative mode, for that matter.) I created a
database that reproduces the error within about a minute of running.
Submitted and, I'm told, accepted during version 16.0. Since then, zero
news and no change. So, for now, I can't rely on files because there is
*no* way to log to files if you can't safely roll them without bringing
down the server.

On macOS, I saw the system pushing errors and launching workers over and
over until I had to force quit it. Wayne Stewart tried it out on Windows
where it crashed 4D. This is for a Windows deployment, for what it's worth.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**

RE: Making LOG EVENT thread-safe

[Epperlein, Lutz (agendo) via 4D_Tech]

A question:
What other approaches did you try to implement a logging feature using 
preemptive threads. I'm pretty sure there is something buried in the threads of 
this mailinglist but I'm not able to find it.

Thanks
Lutz Epperlein

> -Original Message-
> From: 4D_Tech [mailto:4d_tech-boun...@lists.4d.com] On Behalf Of David Adams 
> via
> 4D_Tech
> I finally got around to checking, and LOG EVENT is not a thread-safe
> command. Pity! It would be very handy if this command were usable from a
> preemptive process as it would give us a great way to stream log data out
> to the system for collection by an "agentless" (cough-cough) tool like
> Loggly.
**
4D Internet Users Group (4D iNUG)
FAQ:  http://lists.4d.com/faqnug.html
Archive:  http://lists.4d.com/archives.html
Options: http://lists.4d.com/mailman/options/4d_tech
Unsub:  mailto:4d_tech-unsubscr...@lists.4d.com
**