request_id repeating FAST ... any ideas how this can be?

[oetiker]

A customer just sent me these lines grepped from his server log:

[2020-12-10 12:07:03.84840] [25129] [debug] [WqrYi0CD] GET "/REST/v1/AC/GetChallenge"
[2020-12-10 12:07:03.84908] [25129] [debug] [WqrYi0CD] Routing to controller "XX::Controller::AC" and action "GetChallenge"
[2020-12-10 12:07:03.88480] [25129] [debug] [WqrYi0CD] 200 OK (0.036412s, 27.463/s)
[2020-12-10 12:46:29.75292] [15855] [debug] [WqrYi0CD] GET "/REST/v1/tokenAuth"
[2020-12-10 12:46:29.76529] [15855] [debug] [WqrYi0CD] Routing to controller "XX::Controller::AC" and action "auth"
[2020-12-10 12:46:30.05810] [15855] [debug] [WqrYi0CD] 200 OK (0.305086s, 3.278/s)
[2020-12-10 13:15:52.67958] [36973] [debug] [WqrYi0CD] GET "/REST/v1/tokenAuth"
[2020-12-10 13:15:52.68019] [36973] [debug] [WqrYi0CD] Routing to controller "XX::Controller::AC" and action "auth"
[2020-12-10 13:15:52.79875] [36973] [debug] [WqrYi0CD] 200 OK (0.119107s, 8.396/s)

this is code running with mojo 8.52 ... any ideas how it can be that the request_id repeats so quickly ? These 3 instances are only a fragment of the log. There are 5 more repeats until 2020-12-10 14:56:05.64320.

[oetiker]

could it be that

mojo/lib/Mojo/Message/Request.pm

Line 9 in 907dd0e

my ($SEED, $COUNTER) = ($$ . time . rand, int rand 0xffffff);

only gets executed at server (prefork) startup time and every child starts of with the same settings ?

[kraih]

Does #1619 resolve your issue?

[oetiker]

hmmm I wonder if that is enough ...

looking at the output from this code:

#!/usr/bin/env perl
use v5.22;
sub_a();
print "forking\n";
my $pid = fork();
sub_a();
sub_b();

sub sub_a {
    state $x = $$ ."-". rand;
    print "sub_a running in pid $$. state is $x\n";
}
sub sub_b {
    state $x = $$ ."-". rand;
    print "sub_b running in pid $$. state is $x\n";
}

sub_a running in pid 15092. state is 15092-0.684145208289014
forking
sub_a running in pid 15092. state is 15092-0.684145208289014
sub_b running in pid 15092. state is 15092-0.28342977734016
sub_a running in pid 15093. state is 15092-0.684145208289014
sub_b running in pid 15093. state is 15093-0.28342977734016

I wonder about two things:

a) won't rand always return the same number in the freshly forked processes.

b) if for some reason request_id is called in the master process prior to forking then the states will be get inherited pre initialized (eg because during initialization a useragent requet is performed in the master process).

[oetiker]

just found that srand gets called after forking, so the rand issue is mute, but what about the potential pre-initialization issue in the master process?

[kraih]

The problem should be fixed with 907dd0e...c54ca52.

[oetiker]

What happens if I do:

package My::App;
use Mojo::Base qw(Mojolicious);
use Mojo::Message::Request;
sub startup {
    my $app = shift;
    Mojo::Message::Request->new->request_id;
    ...
}

wouldn't that cause $seed and $counter to be the same for all children ?