ThePrez / ServiceCommander-IBMi

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

[BUG] ERROR: Timed out waiting for service 'Mapepire Server' to start #229

Closed i-enthusiast closed 1 month ago

i-enthusiast commented 1 month ago

Describe the bug I am unable to start the Mapepire service using Service Commander. Environment: V7R5, latest PTFs. EDIT: Similar issue posted in Mapepire Github: https://github.com/Mapepire-IBMi/mapepire-server/issues/67

To Reproduce Mapepire was installed using the instructions under "Option 1: RPM (recommended)" found here: https://mapepire-ibmi.github.io/guides/sysadmin/ I then try to use the following command to launch the service: sc start mapepire

The only output I receive is the following:

Performing operation 'START' on service 'mapepire'
ERROR: Timed out waiting for service 'Mapepire Server' to start

Expected behavior Mapepire should start listening on Port 8076.

Verbose output

bash-5.2$ sc -v start mapepire
Arguments list: [start, mapepire]
Verbose mode enabled
--------------------
Initializing service mapepire
Loading yaml service definition from file /QOpenSys/pkgs/lib/mapepire/mapepire.yaml
Initializing service system_admin1
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_admin1.yaml
Initializing service system_admin2
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_admin2.yaml
Initializing service system_admin3
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_admin3.yaml
Initializing service system_admin4
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_admin4.yaml
Initializing service system_admin5
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_admin5.yaml
Initializing service system_ajs
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_ajs.yaml
Initializing service system_as-central
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-central.yaml
Initializing service system_as-database
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-database.yaml
Initializing service system_as-dtaq
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-dtaq.yaml
Initializing service system_as-file
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-file.yaml
Initializing service system_as-netprt
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-netprt.yaml
Initializing service system_as-rmtcmd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-rmtcmd.yaml
Initializing service system_as-signon
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-signon.yaml
Initializing service system_as-sts
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-sts.yaml
Initializing service system_as-svrmap
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_as-svrmap.yaml
Initializing service system_cimom
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_cimom.yaml
Initializing service system_dbgsvr
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_dbgsvr.yaml
Initializing service system_ddm
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_ddm.yaml
Initializing service system_directoryserver
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_directoryserver.yaml
Initializing service system_ftp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_ftp.yaml
Initializing service system_http_admin
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_http_admin.yaml
Initializing service system_lpd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_lpd.yaml
Initializing service system_netserver
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_netserver.yaml
Initializing service system_pop
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_pop.yaml
Initializing service system_rmc
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_rmc.yaml
Initializing service system_slp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_slp.yaml
Initializing service system_smtp
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_smtp.yaml
Initializing service system_sptprx
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_sptprx.yaml
Initializing service system_sshd
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_sshd.yaml
Initializing service system_telnet
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_telnet.yaml
Initializing service system_webquery
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_webquery.yaml
Initializing service system_ypsjsvr
Loading yaml service definition from file /QOpenSys/etc/sc/services/system/system_ypsjsvr.yaml
Initializing service crond
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/crond.yaml
Initializing service mariadb
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/mariadb.yaml
Initializing service postgres
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/postgres.yaml
Initializing service zenddbi
Loading yaml service definition from file /QOpenSys/etc/sc/services/oss_common/zenddbi.yaml
Performing operation 'START' on service 'mapepire'
database says current time is 2024-09-09-15.10.39
using custom batch job name: MAPEPIRE
using custom sbmJobOpts: JOBQ(QUSRNOMAX)
envp of the child is [PATH=/QOpenSys/pkgs/bin:/QOpenSys/usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/sbin:.:/usr/bin, OPENJ9_JAVA_COMMAND_LINE=/QOpenSys/pkgs/lib/jvm/openjdk-11/bin/java -jar /QOpenSys/pkgs/bin/../lib/sc/sc.jar -v start mapepire, MALLOCOPTIONS=multiheap,considersize, TZ=<CST>6<CDT>,M3.2.0,M11.1.0, TERM=xterm, USER=user01, MAIL=/var/spool/mail/user01, LC_ALL=EN_US.UTF-8, LOGIN=user01, LOGNAME=user01, PWD=/home/user01, HOME=/home/user01, PATH=/QOpenSys/pkgs/bin:/QOpenSys/usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/sbin:.:/usr/bin, PORT=8076, PORT_PLUS_1=8077, PORT_PLUS_2=8078, PORT_PLUS_3=8079, PORT_PLUS_4=8080, PORT_PLUS_5=8081, PORT_PLUS_6=8082, PORT_PLUS_7=8083, PORT_PLUS_8=8084, SCOMMANDER_LOGFILE=/home/user01/.sc/logs/2024-09-09-15.10.39.mapepire.log, SCOMMANDER_TIMESTAMP=2024-09-09-15.10.39, SCOMMANDER_SUBMITTER=user01, SCOMMANDER_NAME=mapepire, SCOMMANDER_FRIENDLY_NAME=Mapepire Server, SCOMMANDER_DEFINED_AT=/QOpenSys/pkgs/lib/mapepire/mapepire.yaml, PASE_FORK_JOBNAME=mapepire, SBMJOB_JOBNAME=MAPEPIRE, SBMJOB_OPTS=JOBQ(QUSRNOMAX)]
running command: exec /home/user01/.sc/.scripts/batch_qp2.v2.sh '../../bin/mapepire >> /home/user01/.sc/logs/2024-09-09-15.10.39.mapepire.log 2>&1'
child process mapepire:Command is > SBMJOB CMD(CALL PGM(QP2SHELL2) PARM('/QOpenSys/pkgs/bin/bash' '-c' 'cd /QOpenSys/pkgs/lib/mapepire && exec ../../bin/mapepire >> /home/user01/.sc/logs/2024-09-09-15.10.39.mapepire.log 2>&1')) CPYENVVAR(*YES) PRTDEV(*USRPRF) ALWMLTTHD(*YES) JOB(MAPEPIRE) JOBQ(QUSRNOMAX)  <
child process mapepire:CPC1221: Job 004301/user01/MAPEPIRE submitted to job queue QUSRNOMAX in library QSYS.
ERROR: Timed out waiting for service 'Mapepire Server' to start

java.lang.RuntimeException
        at jesseg.ibmi.opensource.SCException.<init>(SCException.java:26)
        at jesseg.ibmi.opensource.OperationExecutor.startService(OperationExecutor.java:936)
        at jesseg.ibmi.opensource.OperationExecutor.execute(OperationExecutor.java:200)
        at jesseg.ibmi.opensource.ServiceCommander.performOperationsOnServices(ServiceCommander.java:346)
        at jesseg.ibmi.opensource.ServiceCommander.main(ServiceCommander.java:313)

jesseg.ibmi.opensource.SCException: ERROR: Timed out waiting for service 'Mapepire Server' to start

        at jesseg.ibmi.opensource.OperationExecutor.startService(OperationExecutor.java:936)
        at jesseg.ibmi.opensource.OperationExecutor.execute(OperationExecutor.java:200)
        at jesseg.ibmi.opensource.ServiceCommander.performOperationsOnServices(ServiceCommander.java:346)
        at jesseg.ibmi.opensource.ServiceCommander.main(ServiceCommander.java:313)
Caused by: java.lang.RuntimeException
        at jesseg.ibmi.opensource.SCException.<init>(SCException.java:26)
        ... 4 more

Additional context

ThePrez commented 1 month ago

Bummer. Sorry you are having issues.

Can you please post the contents of /home/user01/.sc/logs/2024-09-09-15.10.39.mapepire.log?

i-enthusiast commented 1 month ago

Thanks for taking the time to respond!

That log file is empty :( I have 5 log files there from all my attempts to start it, and they're all empty.

FYI, I also posted an issue over on mapepire-server: https://github.com/Mapepire-IBMi/mapepire-server/issues/67

Some more environment details: This is a Power 10 (9105-41B) LPAR used for testing. It is being hosted under an IBM i hosting partition that is also running V7R5.

ThePrez commented 1 month ago

Strange. What happens if you try to start it directly, like so?:

/QOpenSys/pkgs/bin/mapepire
i-enthusiast commented 1 month ago

I receive the following output: Starting daemon...2024-09-10 10:44:19.379:INFO::main: Logging initialized @326ms to org.eclipse.jetty.util.log.StdErrLog bye

I don't believe the service is running.

Additional Info

bash-5.2$ sc info mapepire

---------------------------------------------------------------------
mapepire (Mapepire Server)

Defined in: /QOpenSys/pkgs/lib/mapepire/mapepire.yaml

Working Directory: .

Startup Command: ../../bin/mapepire
Startup Wait Time (s): 60

Shutdown Wait Time (s): 45

Check-alive conditions: JOBNAME:MAPEPIRE, PORT:8076
Batch Mode: <submitted to batch>
    Batch Job Name: MAPEPIRE
    SBMJOB options: JOBQ(QUSRNOMAX)

Inherits environment variables?: true
Custom environment variables:
    PATH=/QOpenSys/pkgs/bin:/QOpenSys/usr/bin:/usr/ccs/bin:/QOpenSys/usr/bin/X11:/usr/sbin:.:/usr/bin
---------------------------------------------------------------------
ThePrez commented 1 month ago

Looks like more of a Mapepire problem than SC, but I have no problem chasing here for now. We'll need more logs, unfortunately. Please run the following command:

QIBM_JAVA_STDIO_CONVERT=N QIBM_PASE_DESCRIPTOR_STDIO=B QIBM_USE_DESCRIPTOR_STDIO=Y QIBM_MULTI_THREADED=Y /QOpenSys/QIBM/ProdData/JavaVM/jdk80/64bit/bin/java -Dos400.stdio.convert=N -jar /QOpenSys/pkgs/lib/mapepire/mapepire-server.jar --traceOn

If you ran this command as an *ALLOBJ user, it should generate a file with a .html extension in /QOpenSys/pkgs/lib/mapepire/ Otherwise, it will be an HTML file in /tmp that starts with VSCode

Assuming you are able to successfully complete these steps, please send in the contents of the resulting log file (.html format)

i-enthusiast commented 1 month ago

THANK YOU!!!

All I needed was a way to debug the output during startup, and your command allowed this. With your help I was able to identify and correct the issue.

java.net.UnknownHostException: <redacted.domain.com>: <redacted.domain.com>: Hostname and service name not provided or found
    at java.net.InetAddress.getLocalHost(InetAddress.java:1704)
    at com.github.ibm.mapepire.certstuff.SelfSignedCertGenerator.generate(SelfSignedCertGenerator.java:24)
    at com.github.ibm.mapepire.certstuff.ServerCertGetter.get(ServerCertGetter.java:102)
    at com.github.ibm.mapepire.MapepireServer.main(MapepireServer.java:74)
Caused by: java.net.UnknownHostException: <redacted.domain.com>: Hostname and service name not provided or found
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:1048)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1481)
    at java.net.InetAddress.getLocalHost(InetAddress.java:1699)
    ... 3 more

The server couldn't resolve its own hostname. As this is a brand new LPAR for testing, no DNS records had been set up on the lookup servers. As soon as I created a DNS record for this server's hostname, the service was able to start up.

I recommend this requirement be listed in the Mapepire setup documentation, i.e. full DNS setup (a.k.a fully resolvable hostname). That's not for you to worry about of course, but I'm just including it here for anyone else that may experience this issue.

Thanks again @ThePrez !!!!