You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2016/10/11 23:00:40 UTC

[Bug 60240] New: Duplicate initialization log entry in mod_jk.log

https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

            Bug ID: 60240
           Summary: Duplicate initialization log entry in mod_jk.log
           Product: Tomcat Connectors
           Version: 1.2.42
          Hardware: PC
                OS: Linux
            Status: NEW
          Severity: minor
          Priority: P2
         Component: mod_jk
          Assignee: dev@tomcat.apache.org
          Reporter: mkiss@nauticom.net

Created attachment 34360
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34360&action=edit
mod_jk config file from /etc/httpd/conf.modules.d

I have mod_jk working fine with apache httpd, but I noticed the following
duplicate entries in mod_jk.log during startup:

[Tue Oct 11 12:14:53.621 2016] [7005:140099906832576] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Tue Oct 11 12:14:53.679 2016] [7005:140099906832576] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized

Just concerned the initialization might be happening twice, causing extra
resources to be allocated.

Apache HTTPD version: Apache/2.4.23 (Fedora)
mod_jk version: 1.2.42

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #8 from Rainer Jung <ra...@kippdata.de> ---
Aha, maybe the Apache gets started by systemd?

If so, any chance you can start it manually using apachectl and check, whether
the output changes then. This would be very helpful. We could then likely focus
on startup changes coming from systemd.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #1 from Matthew Kiss <mk...@nauticom.net> ---
Created attachment 34361
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34361&action=edit
mod_jk worker config file from /etc/httpd/conf

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #2 from Matthew Kiss <mk...@nauticom.net> ---
Created attachment 34362
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34362&action=edit
Apache httpd config file from /etc/httpd/conf

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #7 from Matthew Kiss <mk...@nauticom.net> ---
(In reply to Matthew Kiss from comment #6)
> Created attachment 34367 [details]
> Output from 'apachectl fullstatus'

Sorry, this is a duplicate upload.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #4 from Matthew Kiss <mk...@nauticom.net> ---
I'm running httpd as installed by fedora workstation 23 with latest updates and
no custom cmd-line options like -X. I enabled server-status in apache and
restarted everything. Here's the new mod_jk.log output:

[Wed Oct 12 08:46:41.207 2016] [10560:139963972110528] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 08:46:41.265 2016] [10560:139963972110528] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized

Here is the ps output:

root      10560      1  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10562  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10563  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10564  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10583  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10585  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND
apache    10586  10560  0 08:46 ?        00:00:00 /usr/sbin/httpd -DFOREGROUND

Here is the apachectl status output:

● httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled; vendor
preset: disabled)
   Active: active (running) since Wed 2016-10-12 08:46:41 EDT; 6min ago
 Main PID: 10560 (httpd)
   Status: "Total requests: 3; Idle/Busy workers 100/0;Requests/sec: 0.00752;
Bytes served/sec:  35 B/sec"
   CGroup: /system.slice/httpd.service
           ├─10560 /usr/sbin/httpd -DFOREGROUND
           ├─10562 /usr/sbin/httpd -DFOREGROUND
           ├─10563 /usr/sbin/httpd -DFOREGROUND
           ├─10564 /usr/sbin/httpd -DFOREGROUND
           ├─10583 /usr/sbin/httpd -DFOREGROUND
           ├─10585 /usr/sbin/httpd -DFOREGROUND
           └─10586 /usr/sbin/httpd -DFOREGROUND

I will upload an attachment for 'apachectl fullstatus' shortly.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #6 from Matthew Kiss <mk...@nauticom.net> ---
Created attachment 34367
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34367&action=edit
Output from 'apachectl fullstatus'

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #5 from Matthew Kiss <mk...@nauticom.net> ---
Created attachment 34366
  --> https://bz.apache.org/bugzilla/attachment.cgi?id=34366&action=edit
Output from 'apachectl fullstatus'

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

Mark Thomas <ma...@apache.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
         Resolution|---                         |INVALID
             Status|NEW                         |RESOLVED

--- Comment #10 from Mark Thomas <ma...@apache.org> ---
I've just tested this with Fedora Workstation 28 and I see the same thing.

Apart from the duplicate process ID, the behaviour is identical on Ubuntu.

Starting via apachectl on Fedora doesn't help as it has been modified to go via
systemctl. I therefore tried httpd -k  and saw the PID change as expected.

Therefore, this to be a quirk of Fedora / systemctl.

Since this does not appear to affect how httpd / mod_jk works I'm closing this
as not an issue.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #11 from Rainer Jung <ra...@kippdata.de> ---
Aha, the reason seems to be that systemd sets the -D FOREGROUND define at
startup. In httpd code that means it won't call apr_proc_detach during()
startup in the MPM, and part of apr_proc_detach() is a call to fork(). That's
why during "normal" startup there's a second process with a different pid and
during "FOREGROUND" startup like the one used by systemd there's no such
change.

I agree with Mark, that there's no issue observed with the duplicate init so
INVALID seems fine to me.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #3 from Rainer Jung <ra...@kippdata.de> ---
> I have mod_jk working fine with apache httpd, but I noticed the following
> duplicate entries in mod_jk.log during startup:
> 
> [Tue Oct 11 12:14:53.621 2016] [7005:140099906832576] [info]
> init_jk::mod_jk.c (3595): mod_jk/1.2.42 initialized
> [Tue Oct 11 12:14:53.679 2016] [7005:140099906832576] [info]
> init_jk::mod_jk.c (3595): mod_jk/1.2.42 initialized
> 
> Just concerned the initialization might be happening twice, causing extra
> resources to be allocated.
> 
> Apache HTTPD version: Apache/2.4.23 (Fedora)
> mod_jk version: 1.2.42

This behavior is almost normal and hasn't changed during the last releases.

What is strange, is that both lines show the same pid (process id). A normal
startup should show different pids. During Apache startup there's first a
temporary process that will go away and then a second process will stay as the
mother process of all children. One should see first the pid of the temporary
process which will no longer exist after startup, and then the pid of the
mother process that wil stay. In your case we see two times the pid "7005". Can
you double check, whether the numbers are the real ones? The pid is the first
of the two numbers in the square brackets after the timestamp.

Is there anything special about your startup/test? Using "-X" or some exotic
MPM?

Regards,

Rainer

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 60240] Duplicate initialization log entry in mod_jk.log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60240

--- Comment #9 from Matthew Kiss <mk...@nauticom.net> ---
(In reply to Rainer Jung from comment #8)
> Aha, maybe the Apache gets started by systemd?
> 
> If so, any chance you can start it manually using apachectl and check,
> whether the output changes then. This would be very helpful. We could then
> likely focus on startup changes coming from systemd.

[root@localhost httpd]# systemctl disable httpd
Removed symlink /etc/systemd/system/multi-user.target.wants/httpd.service.

<reboot>

[root@localhost ~]# ps -ef | grep httpd
root       2551   2509  0 21:30 pts/0    00:00:00 grep --color=auto httpd

[root@localhost ~]# apachectl status
? httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; vendor
preset: disabled)
   Active: inactive (dead)

[root@localhost ~]# apachectl start

[root@localhost ~]# apachectl status
? httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; vendor
preset: disabled)
   Active: active (running) since Wed 2016-10-12 21:31:51 EDT; 10s ago
 Main PID: 2570 (httpd)
   Status: "Total requests: 0; Idle/Busy workers 100/0;Requests/sec: 0; Bytes
served/sec:   0 B/sec"
   CGroup: /system.slice/httpd.service
           +-2570 /usr/sbin/httpd -DFOREGROUND
           +-2617 /usr/sbin/httpd -DFOREGROUND
           +-2618 /usr/sbin/httpd -DFOREGROUND
           +-2639 /usr/sbin/httpd -DFOREGROUND
           +-2644 /usr/sbin/httpd -DFOREGROUND
           +-2648 /usr/sbin/httpd -DFOREGROUND
           +-2653 /usr/sbin/httpd -DFOREGROUND

Oct 12 21:31:51 localhost.localdomain systemd[1]: Starting The Apache HTTP
Server...
Oct 12 21:31:51 localhost.localdomain systemd[1]: Started The Apache HTTP
Server.

[root@localhost ~]# tail -10 /etc/httpd/logs/mod_jk.log
[Tue Oct 11 12:14:11.030 2016] [6704:140664125495488] [warn]
service::jk_status.c (4840): Status worker 'jk-manager' service denied for user
'jkadmin' [Basic] from 192.168.0.4 [(null)]
[Tue Oct 11 12:14:11.031 2016] [6704:140664125495488] [warn]
service::jk_status.c (5200): Status worker 'jk-manager': Access denied.
[Tue Oct 11 12:14:53.621 2016] [7005:140099906832576] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Tue Oct 11 12:14:53.679 2016] [7005:140099906832576] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 08:42:17.630 2016] [10247:139872252934336] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 08:42:17.689 2016] [10247:139872252934336] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 08:46:41.207 2016] [10560:139963972110528] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 08:46:41.265 2016] [10560:139963972110528] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 21:31:51.604 2016] [2570:139932261046464] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized
[Wed Oct 12 21:31:51.775 2016] [2570:139932261046464] [info] init_jk::mod_jk.c
(3595): mod_jk/1.2.42 initialized

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org