search

ThePrez / ServiceCommander-IBMi

Service Commander for IBM i
Apache License 2.0
40 stars 12 forks source link

[BUG] #223

Closed JDubbTX closed 1 year ago

JDubbTX commented 1 year ago

Describe the bug jenkins service times out waiting for it to start

To Reproduce using this jenkins.yml service:

name: Jenkins
dir: /home/jweiric9/jenkins
start_cmd: java -Djava.net.preferIPv4Stack=true -jar jenkins.war --httpPort=9090

check_alive: 5000
batch_mode: true
sbmjob_jobname: JENKINS
sbmjob_opts: JOBQ(QUSRNOMAX)

environment_vars:
- HOME=/home/JWEIRIC9
- JAVA_HOME=/QOpenSys/pkgs/lib/jvm/openjdk-11
- PATH=/QOpenSys/pkgs/bin:/QOpenSys/usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/sbin:.:/usr/bin

run sc start jenkins

Expected behavior jenkins starts, sc is happy.

Verbose output Run the command with the -v option and share the output here.

~/jenkins$ sc start jenkins -v
Arguments list: [start, jenkins]
Verbose mode enabled
--------------------
Initializing service system_admin1
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_admin1.yaml
Initializing service system_admin2
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_admin2.yaml
Initializing service system_admin3
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_admin3.yaml
Initializing service system_admin4
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_admin4.yaml
Initializing service system_admin5
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_admin5.yaml
Initializing service system_ajs
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_ajs.yaml
Initializing service system_as-central
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-central.yaml
Initializing service system_as-database
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-database.yaml
Initializing service system_as-dtaq
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-dtaq.yaml
Initializing service system_as-file
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-file.yaml
Initializing service system_as-netprt
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-netprt.yaml
Initializing service system_as-rmtcmd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-rmtcmd.yaml
Initializing service system_as-signon
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-signon.yaml
Initializing service system_as-sts
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-sts.yaml
Initializing service system_as-svrmap
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_as-svrmap.yaml
Initializing service system_cimom
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_cimom.yaml
Initializing service system_dbgsvr
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_dbgsvr.yaml
Initializing service system_ddm
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_ddm.yaml
Initializing service system_directoryserver
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_directoryserver.yaml
Initializing service system_ftp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_ftp.yaml
Initializing service system_http_admin
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_http_admin.yaml
Initializing service system_lpd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_lpd.yaml
Initializing service system_netserver
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_netserver.yaml
Initializing service system_pop
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_pop.yaml
Initializing service system_rmc
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_rmc.yaml
Initializing service system_slp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_slp.yaml
Initializing service system_smtp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_smtp.yaml
Initializing service system_sptprx
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_sptprx.yaml
Initializing service system_sshd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_sshd.yaml
Initializing service system_telnet
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_telnet.yaml
Initializing service system_webquery
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_webquery.yaml
Initializing service system_ypsjsvr
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/syste                                                                m_ypsjsvr.yaml
Initializing service crond
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/c                                                                rond.yaml
Initializing service mariadb
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/m                                                                ariadb.yaml
Initializing service postgres
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/p                                                                ostgres.yaml
Initializing service zenddbi
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/z                                                                enddbi.yaml
Initializing service camel
Loading yaml service definition from file /home/JWEIRIC9/.sc/services/camel.yml
Initializing service jenkins
Loading yaml service definition from file /home/JWEIRIC9/.sc/services/jenkins.ym                                                                l
Performing operation 'START' on service 'jenkins'
database says current time is 2023-09-19-11.09.23
using custom batch job name: JENKINS
using custom sbmJobOpts: JOBQ(QUSRNOMAX)
envp of the child is [PATH=/QOpenSys/QIBM/ProdData/JavaVM/jdk11/64bit/bin:/home/                                                                JWEIRIC9/.local/bin:/QOpensys/pkgs/lib/nodejs16/bin:/QOpenSys/pkgs/bin:/QOpenSys                                                                /usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/sbin:.:/usr/bin, OPENJ9_JAVA_CO                                                                MMAND_LINE=/QOpenSys/pkgs/lib/jvm/openjdk-11/bin/java -jar /QOpenSys/pkgs/bin/..                                                                /lib/sc/sc.jar start jenkins -v, MALLOCOPTIONS=multiheap,considersize, LIB=RDGJW                                                                EIRIC, TZ=<UTC-05x00S>5, OLDPWD=/home/JWEIRIC9/.sc, TERM=xterm, USER=jweiric9, J                                                                ENKINS_HOME=/home/JWEIRIC9/.jenkins, MAIL=/var/spool/mail/jweiric9, LC_ALL=EN_US                                                                .UTF-8, LOGIN=jweiric9, LOGNAME=jweiric9, PWD=/home/JWEIRIC9/jenkins, HOME=/home                                                                /JWEIRIC9, HOME=/home/JWEIRIC9, JAVA_HOME=/QOpenSys/pkgs/lib/jvm/openjdk-11, PAT                                                                H=/QOpenSys/pkgs/bin:/QOpenSys/usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/s                                                                bin:.:/usr/bin, PORT=5000, PORT_PLUS_1=5001, PORT_PLUS_2=5002, PORT_PLUS_3=5003,                                                                 PORT_PLUS_4=5004, PORT_PLUS_5=5005, PORT_PLUS_6=5006, PORT_PLUS_7=5007, PORT_PL                                                                US_8=5008, SCOMMANDER_LOGFILE=/home/JWEIRIC9/.sc/logs/2023-09-19-11.09.23.jenkin                                                                s.log, SCOMMANDER_TIMESTAMP=2023-09-19-11.09.23, SCOMMANDER_SUBMITTER=jweiric9,                                                                 SCOMMANDER_NAME=jenkins, SCOMMANDER_FRIENDLY_NAME=Jenkins, SCOMMANDER_DEFINED_AT                                                                =/home/JWEIRIC9/.sc/services/jenkins.yml, PASE_FORK_JOBNAME=jenkins, SBMJOB_JOBN                                                                AME=JENKINS, SBMJOB_OPTS=JOBQ(QUSRNOMAX)]
running command: exec /home/JWEIRIC9/.sc/.scripts/batch_qp2.v1.sh 'java -Djava.n                                                                et.preferIPv4Stack=true -jar jenkins.war --httpPort=9090 >> /home/JWEIRIC9/.sc/l                                                                ogs/2023-09-19-11.09.23.jenkins.log 2>&1'
child process jenkins:Command is > SBMJOB CMD(CALL PGM(QP2SHELL2) PARM('/QOpenSy                                                                s/pkgs/bin/bash' '-c' 'cd /home/JWEIRIC9/jenkins && env && exec java -Djava.net.                                                                preferIPv4Stack=true -jar jenkins.war --httpPort=9090 >> /home/JWEIRIC9/.sc/logs                                                                /2023-09-19-11.09.23.jenkins.log 2>&1')) CPYENVVAR(*YES) PRTDEV(*USRPRF) ALWMLTT                                                                HD(*YES) JOB(JENKINS) JOBQ(QUSRNOMAX)  <
child process jenkins:CPC1221: Job 604527/JWEIRIC9/JENKINS submitted to job queu                                                                e QUSRNOMAX in library QSYS.
child process 2023-09-19-11.09.23.jenkins.log:Running from: /home/JWEIRIC9/jenki                                                                ns/jenkins.war
child process 2023-09-19-11.09.23.jenkins.log:webroot: /home/JWEIRIC9/.jenkins/w                                                                ar
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:33.961+0000 [id=1]       INFO    winsto                                          ne.Logger#logInternal: Beginning extraction from war file
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:34.151+0000 [id=1]       WARNING o.e.j.                                          s.handler.ContextHandler#setContextPath: Empty contextPath
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:34.306+0000 [id=1]       INFO    org.ec                                          lipse.jetty.server.Server#doStart: jetty-10.0.15; built: 2023-04-11T17:25:14.480Z; git: 68017dbd00236b                                          b7e187330d7585a059610f661d; jvm 11.0.15-ea+10
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:35.039+0000 [id=1]       INFO    o.e.j.                                          w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.J                                          ettyJspServlet
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:35.160+0000 [id=1]       INFO    o.e.j.                                          s.s.DefaultSessionIdManager#doStart: Session workerName=node0
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:35.840+0000 [id=1]       INFO    hudson                                          .WebAppMain#contextInitialized: Jenkins home directory: /home/JWEIRIC9/.jenkins found at: $user.home/.                                          jenkins
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:36.019+0000 [id=1]       INFO    o.e.j.                                          s.handler.ContextHandler#doStart: Started w.@4987103{Jenkins v2.414.1,/,file:///home/JWEIRIC9/.jenkins                                          /war/,AVAILABLE}{/home/JWEIRIC9/.jenkins/war}
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:36.064+0000 [id=1]       INFO    o.e.j.                                          server.AbstractConnector#doStart: Started ServerConnector@edf5ebd5{HTTP/1.1, (http/1.1)}{0.0.0.0:9090}
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:36.089+0000 [id=1]       INFO    org.ec                                          lipse.jetty.server.Server#doStart: Started Server@82020637{STARTING}[10.0.15,sto=0] @11391ms
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:36.092+0000 [id=114]     INFO    winsto                                          ne.Logger#logInternal: Winstone Servlet Engine running: controlPort=disabled
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:36.652+0000 [id=122]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Started initialization
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:37.206+0000 [id=160]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Listed all plugins
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:46.523+0000 [id=143]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Prepared all plugins
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:46.556+0000 [id=143]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Started all plugins
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:46.572+0000 [id=179]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Augmented all extensions
child process 2023-09-19-11.09.23.jenkins.log:WARNING: An illegal reflective access operation has occu                                          rred
child process 2023-09-19-11.09.23.jenkins.log:WARNING: Illegal reflective access by org.codehaus.groov                                          y.vmplugin.v7.Java7$1 (file:/home/JWEIRIC9/.jenkins/war/WEB-INF/lib/groovy-all-2.4.21.jar) to construc                                          tor java.lang.invoke.MethodHandles$Lookup(java.lang.Class,int)
child process 2023-09-19-11.09.23.jenkins.log:WARNING: Please consider reporting this to the maintaine                                          rs of org.codehaus.groovy.vmplugin.v7.Java7$1
child process 2023-09-19-11.09.23.jenkins.log:WARNING: Use --illegal-access=warn to enable warnings of                                           further illegal reflective access operations
child process 2023-09-19-11.09.23.jenkins.log:WARNING: All illegal access operations will be denied in                                           a future release
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:47.266+0000 [id=169]     INFO    h.p.b.                                          g.GlobalTimeOutConfiguration#load: global timeout not set
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:48.465+0000 [id=131]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: System config loaded
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:48.467+0000 [id=185]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: System config adapted
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:48.826+0000 [id=152]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Loaded all jobs
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:48.883+0000 [id=152]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Configuration for all jobs updated
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:48.943+0000 [id=205]     INFO    hudson                                          .util.Retrier#start: Attempt #1 to do the action check updates server
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:49.096+0000 [id=159]     INFO    jenkin                                          s.InitReactorRunner$1#onAttained: Completed initialization
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:49.195+0000 [id=104]     INFO    hudson                                          .lifecycle.Lifecycle#onReady: Jenkins is fully up and running
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:55:54.364+0000 [id=213]     WARNING h.n.Ab                                          stractAsyncNodeMonitorDescriptor#error: Failed to monitor Built-In Node for Free Swap Space
child process 2023-09-19-11.09.23.jenkins.log:java.io.IOException: No suitable implementation found: o                                          s.name=OS400 os.arch=ppc64 sun.arch.data.model=64
child process 2023-09-19-11.09.23.jenkins.log:  at org.jvnet.hudson.MemoryMonitor.obtain(MemoryMonitor                                          .java:93)
child process 2023-09-19-11.09.23.jenkins.log:  at org.jvnet.hudson.MemoryMonitor.get(MemoryMonitor.ja                                          va:59)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.node_monitors.SwapSpaceMonitor$MonitorTask.c                                          all(SwapSpaceMonitor.java:125)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.node_monitors.SwapSpaceMonitor$MonitorTask.c                                          all(SwapSpaceMonitor.java:120)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.remoting.LocalChannel.lambda$callAsync$0(Loc                                          alChannel.java:54)
child process 2023-09-19-11.09.23.jenkins.log:  at jenkins.util.ContextResettingExecutorService$2.call                                          (ContextResettingExecutorService.java:46)
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.util.concurrent.FutureTask.run(Futur                                          eTask.java:264)
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.util.concurrent.ThreadPoolExecutor.r                                          unWorker(ThreadPoolExecutor.java:1128)
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.util.concurrent.ThreadPoolExecutor$W                                          orker.run(ThreadPoolExecutor.java:628)
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.lang.Thread.run(Thread.java:871)
child process 2023-09-19-11.09.23.jenkins.log:Caused: java.util.concurrent.ExecutionException
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.util.concurrent.FutureTask.report(Fu                                          tureTask.java:122)
child process 2023-09-19-11.09.23.jenkins.log:  at java.base/java.util.concurrent.FutureTask.get(Futur                                          eTask.java:205)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.remoting.LocalChannel$1.get(LocalChannel.jav                                          a:85)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.node_monitors.AbstractAsyncNodeMonitorDescri                                          ptor.monitorDetailed(AbstractAsyncNodeMonitorDescriptor.java:112)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.node_monitors.AbstractAsyncNodeMonitorDescri                                          ptor.monitor(AbstractAsyncNodeMonitorDescriptor.java:76)
child process 2023-09-19-11.09.23.jenkins.log:  at hudson.node_monitors.AbstractNodeMonitorDescriptor$                                          Record.run(AbstractNodeMonitorDescriptor.java:305)
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:56:08.740+0000 [id=205]     INFO    h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Maven.MavenInstaller
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:56:09.006+0000 [id=205]     INFO    h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Ant.AntInstaller
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:56:09.401+0000 [id=205]     INFO    h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.plugins.gradle.GradleInstaller
child process 2023-09-19-11.09.23.jenkins.log:2023-09-19 16:56:09.402+0000 [id=205]     INFO    hudson.util.Retrier#start: Performed the action check updates server successfully at the attempt #1
**ERROR: Timed out waiting for service 'Jenkins' to start**

java.lang.RuntimeException
        at jesseg.ibmi.opensource.SCException.<init>(SCException.java:26)
        at jesseg.ibmi.opensource.OperationExecutor.startService(OperationExecutor.java:934)
        at jesseg.ibmi.opensource.OperationExecutor.execute(OperationExecutor.java:198)
        at jesseg.ibmi.opensource.ServiceCommander.performOperationsOnServices(ServiceCommander.java:329)
        at jesseg.ibmi.opensource.ServiceCommander.main(ServiceCommander.java:297)

For details, see log file at: /home/JWEIRIC9/.sc/logs/2023-09-19-11.09.23.jenkins.log
jesseg.ibmi.opensource.SCException: ERROR: Timed out waiting for service 'Jenkins' to start

        at jesseg.ibmi.opensource.OperationExecutor.startService(OperationExecutor.java:934)
        at jesseg.ibmi.opensource.OperationExecutor.execute(OperationExecutor.java:198)
        at jesseg.ibmi.opensource.ServiceCommander.performOperationsOnServices(ServiceCommander.java:329)
        at jesseg.ibmi.opensource.ServiceCommander.main(ServiceCommander.java:297)
Caused by: java.lang.RuntimeException
        at jesseg.ibmi.opensource.SCException.<init>(SCException.java:26)
        ... 4 more

Additional context Despite this, jenkins does appear started and I can log into it, and run jobs but SC has no knowledge of the active job and I cannot use sc stop jenkins to end it. When I run that it says 'Service 'Jenkins' is already stopped. but its not.

JDubbTX commented 1 year ago

OK, tried changing check_alive to 9090 and now it works. user error.