Systemd startup script causing problems

anaigini

New Member
Credits
0
Hi,

I created a customized script to start some of the processes in our servers. One of it is httpd :

Code:
[[email protected] system]# cat httpd.service
[Unit]
Description=The Apache HTTP Server
After=network.target remote-fs.target nss-lookup.target

[Service]
Type=notify
#EnvironmentFile=/opt/rh/httpd24/root/etc/sysconfig/httpd
#ExecStart=/usr/local/apache-2.4.33/bin/httpd $OPTIONS -DFOREGROUND
ExecStart=/usr/local/apache-2.4.33/bin/httpd -k start
ExecReload=/usr/local/apache-2.4.33/bin/httpd $OPTIONS -k graceful
ExecStop=/bin/kill -WINCH ${MAINPID}

# We want systemd to give httpd some time to finish gracefully, but still want
# it to kill httpd after TimeoutStopSec if something went wrong during the
# graceful stop. Normally, Systemd sends SIGTERM signal right after the
# ExecStop, which would kill httpd. We are sending useless SIGCONT here to give
# httpd time to finish.
KillSignal=SIGCONT
PrivateTmp=true

[Install]
WantedBy=multi-user.target
[[email protected] system]#
I can reload the service. However, when I attempt to start it, I get error :

Code:
[[email protected] logs]# systemctl status httpd
● httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; disabled; vendor preset: disabled)
   Active: failed (Result: timeout) since Thu 2019-12-19 15:16:38 +08; 1h 30min ago
  Process: 29026 ExecStop=/bin/kill -WINCH ${MAINPID} (code=exited, status=1/FAILURE)
  Process: 29022 ExecStart=/usr/local/apache-2.4.33/bin/httpd -k start (code=exited, status=0/SUCCESS)
 Main PID: 29022 (code=exited, status=0/SUCCESS)

Dec 19 15:15:08 dev1-myeg.int.myeg.com.my systemd[1]: Starting The Apache HTTP Server...
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my kill[29026]: kill: cannot find process ""
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my systemd[1]: httpd.service: control process exited, code=exited status=1
Dec 19 15:16:38 dev1-myeg.int.myeg.com.my systemd[1]: httpd.service stop-sigterm timed out. Killing.
Dec 19 15:16:38 dev1-myeg.int.myeg.com.my systemd[1]: Failed to start The Apache HTTP Server.
Dec 19 15:16:38 dev1-myeg.int.myeg.com.my systemd[1]: Unit httpd.service entered failed state.
Dec 19 15:16:38 dev1-myeg.int.myeg.com.my systemd[1]: httpd.service failed.
[[email protected] logs]#
This is the error logged in journalctl -xe :

Code:
Dec 19 15:14:02 dev1-myeg.int.myeg.com.my postfix/bounce[28209]: 79383479D7F: sender non-delivery notification: 89A5C47C211
Dec 19 15:14:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 79383479D7F: removed
Dec 19 15:14:02 dev1-myeg.int.myeg.com.my postfix/local[28208]: 89A5C47C211: to=<[email protected]>, relay=local, delay=0.02, delays=0.01/0/0/0.01, dsn=5.2.2, status=bounced (c
Dec 19 15:14:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 89A5C47C211: removed
Dec 19 15:14:09 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:14:09+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server
Dec 19 15:14:38 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:14:38+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http:/
Dec 19 15:14:49 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:14:49+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server
Dec 19 15:14:50 dev1-myeg.int.myeg.com.my polkitd[3254]: Registered Authentication Agent for unix-process:28967:805245139 (system bus name :1.277996 [/usr/bin/pkttyagent --notify-fd 5 --fal
Dec 19 15:14:50 dev1-myeg.int.myeg.com.my systemd[1]: Reloading.
Dec 19 15:14:51 dev1-myeg.int.myeg.com.my polkitd[3254]: Unregistered Authentication Agent for unix-process:28967:805245139 (system bus name :1.277996, object path /org/freedesktop/PolicyKi
Dec 19 15:15:01 dev1-myeg.int.myeg.com.my systemd[1]: Started Session 137606 of user root.
-- Subject: Unit session-137606.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-137606.scope has finished starting up.
--
-- The start-up result is done.
Dec 19 15:15:01 dev1-myeg.int.myeg.com.my CROND[28999]: (root) CMD (cd /usr/local/apache31-MYEG/htdocs/myeg_new_ui && php artisan get:survey > /usr/local/apache31-MYEG/logs/getsurvey-cron.l
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/pickup[25832]: 801D8479D7F: uid=0 from=<root>
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/cleanup[28206]: 801D8479D7F: message-id=<[email protected]>
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 801D8479D7F: from=<[email protected]>, size=2539, nrcpt=1 (queue active)
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/local[28208]: 801D8479D7F: to=<[email protected]>, orig_to=<root>, relay=local, delay=0.43, delays=0.41/0/0/0.02, dsn=5.2.2, s
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/cleanup[28206]: 889D247C211: message-id=<[email protected]>
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 889D247C211: from=<>, size=4538, nrcpt=1 (queue active)
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/bounce[28209]: 801D8479D7F: sender non-delivery notification: 889D247C211
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 801D8479D7F: removed
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/local[28208]: 889D247C211: to=<[email protected]>, relay=local, delay=0.02, delays=0.01/0/0/0.01, dsn=5.2.2, status=bounced (c
Dec 19 15:15:02 dev1-myeg.int.myeg.com.my postfix/qmgr[5740]: 889D247C211: removed
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my polkitd[3254]: Registered Authentication Agent for unix-process:29016:805246855 (system bus name :1.277999 [/usr/bin/pkttyagent --notify-fd 5 --fal
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my systemd[1]: Starting The Apache HTTP Server...
-- Subject: Unit httpd.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit httpd.service has begun starting up.
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my kill[29026]: kill: cannot find process ""
Dec 19 15:15:08 dev1-myeg.int.myeg.com.my systemd[1]: httpd.service: control process exited, code=exited status=1
Dec 19 15:15:18 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:15:18+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http:/
Dec 19 15:15:29 dev1-myeg.int.myeg.com.my userhelper[29136]: pam_succeed_if(ovirt-container-list:auth): requirement "user = ovirtagent" was met by user "ovirtagent"
Dec 19 15:15:29 dev1-myeg.int.myeg.com.my userhelper[29136]: running '/usr/share/ovirt-guest-agent/container-list' with root privileges on behalf of 'ovirtagent'
Dec 19 15:15:29 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:15:29+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server
Dec 19 15:15:58 dev1-myeg.int.myeg.com.my graylog-collector-sidecar[3251]: time="2019-12-19T15:15:58+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http:/
Dec 19 15:16:01 dev1-myeg.int.myeg.com.my systemd[1]: Started Session 137607 of user root.
-- Subject: Unit session-137607.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-137607.scope has finished starting up.
lines 1410-1458/1515 96%
This is the httpd error logs :

Code:
[Thu Dec 19 15:15:08.522704 2019] [ssl:warn] [pid 29022:tid 140066466289472] AH01906: dev1.myeg.com.my:443:0 server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Thu Dec 19 15:15:08.532567 2019] [jk:warn] [pid 29022:tid 140066466289472] No JkShmFile defined in httpd.conf. Using default /usr/local/apache-2.4.33/logs/jk-runtime-status
[Thu Dec 19 15:15:08.556561 2019] [jk:error] [pid 29022] [Thu Dec 19 15:15:08 2019][29022:140066466289472] [debug] jk_shm_close::jk_shm.c (745): Closed shared memory /usr/local/apache-2.4.33/logs/jk-runtime-status.29022 childs=1
[Thu Dec 19 15:15:08.861044 2019] [ssl:warn] [pid 29025:tid 140066466289472] AH01906: dev1.myeg.com.my:443:0 server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Thu Dec 19 15:15:09.104449 2019] [jk:warn] [pid 29025:tid 140066466289472] No JkShmFile defined in httpd.conf. Using default /usr/local/apache-2.4.33/logs/jk-runtime-status
[Thu Dec 19 15:15:09.142371 2019] [mpm_event:notice] [pid 29025:tid 140066466289472] AH00489: Apache/2.4.33 (Unix) OpenSSL/1.0.2o PHP/5.6.36 mod_jk/1.2.43 configured -- resuming normal operations
[Thu Dec 19 15:15:09.142464 2019] [core:notice] [pid 29025:tid 140066466289472] AH00094: Command line: '/usr/local/apache-2.4.33/bin/httpd'
(END)
This is in the httpd access logs :

Code:
46.229.168.161 - - [19/Dec/2019:14:04:03 +0800] "GET /robots.txt HTTP/1.1" 200 24 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)" TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
46.229.168.163 - - [19/Dec/2019:14:04:05 +0800] "GET /career/mymotor HTTP/1.1" 200 5341 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)" TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
45.56.78.64 - - [19/Dec/2019:14:24:15 +0800] "GET /?0628182016134805143312 HTTP/1.1" 400 226
64.233.172.106 - - [19/Dec/2019:15:03:04 +0800] "GET /eservices/ HTTP/1.1" 200 1607
64.233.172.108 - - [19/Dec/2019:15:03:04 +0800] "GET /common/img/favicon.ico HTTP/1.1" 200 32942
(END)
This is in /var/log/messages :

Code:
Dec 19 15:14:50 dev1-myeg systemd: Reloading.
Dec 19 15:15:01 dev1-myeg systemd: Started Session 137606 of user root.
Dec 19 15:15:08 dev1-myeg systemd: Starting The Apache HTTP Server...
Dec 19 15:15:08 dev1-myeg kill: kill: cannot find process ""
Dec 19 15:15:08 dev1-myeg systemd: httpd.service: control process exited, code=exited status=1
Dec 19 15:15:18 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:15:18+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/ap
i/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:15:29 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:15:29+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put http://13.228.17
8.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:15:58 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:15:58+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/ap
i/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:16:01 dev1-myeg systemd: Started Session 137607 of user root.
Dec 19 15:16:09 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:16:09+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put http://13.228.17
8.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:16:38 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:16:38+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/ap
i/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:16:38 dev1-myeg systemd: httpd.service stop-sigterm timed out. Killing.
Dec 19 15:16:38 dev1-myeg systemd: Failed to start The Apache HTTP Server.
Dec 19 15:16:38 dev1-myeg systemd: Unit httpd.service entered failed state.
Dec 19 15:16:38 dev1-myeg systemd: httpd.service failed.
Dec 19 15:16:49 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:16:49+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:17:01 dev1-myeg systemd: Started Session 137608 of user root.
Dec 19 15:17:18 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:17:18+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:17:29 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:17:29+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:17:58 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:17:58+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:18:01 dev1-myeg systemd: Started Session 137609 of user root.
Dec 19 15:18:09 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:18:09+08:00" level=error msg="[UpdateRegistration] Failed to report collector status to server: Put http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout"
Dec 19 15:18:38 dev1-myeg graylog-collector-sidecar: time="2019-12-19T15:18:38+08:00" level=error msg="[RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/ap:
I notice that somehow the graylog-collector-sidecar errors also show after the httpd failures, and also a lot of messages on "ovirt" appear together with them too. How are all of these related?

I ran the command :

Code:
# /usr/bin/graylog-collector-sidecar -debug
And this is the output I get :

Code:
[[email protected] collector-sidecar]# /usr/bin/graylog-collector-sidecar -debug
INFO[0000] Using collector-id: 3fb08426-6b4b-4928-969f-913cb690dc3f
INFO[0000] No node-id was configured, falling back to hostname
INFO[0000] Fetching configurations tagged by: [laravel apache]
DEBU[0000] Creating rotated log writer for: /var/log/graylog/collector-sidecar/collector_sidecar.log.%Y%m%d%H%M
DEBU[0000] Add collector backend: filebeat
INFO[0000] Starting signal distributor
DEBU[0000] [signal-processor] (seq=1) handling cmd: restart
INFO[0000] [filebeat] Starting (exec driver)
DEBU[0000] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0000] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0000] [signal-processor] (seq=1) cmd done: restart
ERRO[0001] [filebeat] Backend finished unexpectedly, trying to restart 1/3.
DEBU[0001] [signal-processor] (seq=2) handling cmd: restart
INFO[0001] [filebeat] Stopping
DEBU[0003] [filebeat] SIGHUP ignored, killing process
DEBU[0003] [filebeat] Failed to kill process os: process already finished
INFO[0003] [filebeat] Starting (exec driver)
DEBU[0003] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0003] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0003] [signal-processor] (seq=2) cmd done: restart
ERRO[0004] [filebeat] Backend finished unexpectedly, trying to restart 2/3.
DEBU[0004] [signal-processor] (seq=3) handling cmd: restart
INFO[0004] [filebeat] Stopping
DEBU[0006] [filebeat] SIGHUP ignored, killing process
DEBU[0006] [filebeat] Failed to kill process os: process already finished
INFO[0006] [filebeat] Starting (exec driver)
DEBU[0006] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0006] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0006] [signal-processor] (seq=3) cmd done: restart
ERRO[0007] [filebeat] Backend finished unexpectedly, trying to restart 3/3.
DEBU[0007] [signal-processor] (seq=4) handling cmd: restart
INFO[0007] [filebeat] Stopping
DEBU[0009] [filebeat] SIGHUP ignored, killing process
DEBU[0009] [filebeat] Failed to kill process os: process already finished
INFO[0009] [filebeat] Starting (exec driver)
DEBU[0009] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0009] Creating rotated log writer for: /var/log/graylog/collector-sidecar/filebeat_stderr.log.%Y%m%d%H%M
DEBU[0009] [signal-processor] (seq=4) cmd done: restart
ERRO[0010] [filebeat] Unable to start collector after 3 tries, giving up!







ERRO[1800] [RequestConfiguration] Fetching configuration failed: Get http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/3fb08426-6b4b-4928-969f-913cb690dc3f?tags=%5B%22laravel%22%2C%22apache%22%5D: dial tcp 13.228.178.92:9000: i/o timeout
ERRO[1800] [UpdateRegistration] Failed to report collector status to server: Put http://13.228.178.92:9000/api/plugins/org.graylog.plugins.collector/collectors/3fb08426-6b4b-4928-969f-913cb690dc3f: dial tcp 13.228.178.92:9000: i/o timeout
Please help me debug the error/problem, as I am not sure where & how to start.
 


LTXex

New Member
Credits
15
Hi
Have you tried a different systemd script to see if you can isolate the issue?
Maybe the one below would work or at least show different errors

[Unit]

Description=The Apache HTTP Server
After=network.target

[Service]
Type=forking
ExecStart=/usr/local/apache-2.4.33/bin/httpd -k start
ExecReload=/usr/local/apache-2.4.33/bin/apachectl -k graceful
ExecStop=/usr/local/apache-2.4.33/bin/apachectl -k graceful-stop
PIDFile=/usr/local/apache-2.4.33/logs/httpd.pid
PrivateTmp=true

[Install]
WantedBy=multi-user.target
 


Staff online

Members online


Top