Installed MID server but I'm getting a "duplicate name" error in the logs and the MID won't work

[tspitalnick]

I have a new, clean London dev instance and downloaded the mid, set up the install and it worked just fine. I gave my MID a totally unique name and it's logging in via my admin credential (I know, I know, but it's just a dev instance). I do the startup, the MID shows up in my instance, I validate, but then I get this:


10/30/18 09:14:51 (244) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
10/30/18 09:14:51 (244) StartupSequencer Waiting to retry in 5 minutes. Attempt 1 of 3.
10/30/18 09:19:51 (879) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
10/30/18 09:19:51 (880) StartupSequencer Waiting to retry in 5 minutes. Attempt 2 of 3.
10/30/18 09:24:52 (486) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
10/30/18 09:24:52 (486) StartupSequencer Waiting to retry in 5 minutes. Attempt 3 of 3.

10/30/18 09:29:54 (424) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
10/30/18 09:29:55 (210) StartupSequencer Stopping MID Server due to exceeding retry attempts.

Then it shuts down for good. I absolutely do not have another MID by the same name. I DO have another mid that still exists from a prior install, but it is confirmed that the service is inactive and definitely a different name.

Any ideas?

Edit: In the MID unresolved issues, this came up: "A MID Server with a duplicate name or sys_id was prevented from connecting. Install path: C:\agent-london. This issue must be manually resolved."

[tspitalnick]

FWIW I tried updating Java to the newest 64-bit release. Same issue.

I had a coworker try to install a MID into my instance from HIS computer using the same MID zip. His was successful and has none of the errors I see. This leads me to believe it's something weird in my computer?

[tspitalnick]

Anyone have any ideas? This is still happening.

[Miguel Sanchez]

Hi Toby

I doubt that the issue could be related to the host machine... we have in the same system two MID servers (one for Evanios and one for Discovery).

The one dedicated to Evanios is OK, and the one dedicated to Discovery is showing the same problem than yours.

We've noticed that in our case, it occurs after an internal Java error (below I've added the extract...) and the server tries to restart itself.... not sure if in your case is the same (you are using Discovery as well or after an internal crash)...

Let's see if at least we found a pattern that help us to address it....

KR

Miguel

 Here the log extract: 

12/27/18 20:49:14 (809) SSHClientEngine WARNING *** WARNING *** Unexpectedly high SSHClientEngine select polling period: 9.0s
12/27/18 20:49:14 (809) SSHClientEngine DEBUG: Loop Head: 0
12/27/18 20:49:18 (684) SSHClientEngine DEBUG: Read: 1
12/27/18 20:49:18 (684) SSHClientEngine DEBUG:

12/27/18 20:49:20 (903) ECCQueueMonitor.40 WARNING *** WARNING *** javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
12/27/18 20:49:20 (903) ECCQueueMonitor.40 SEVERE *** ERROR *** getRecords failed (javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake)
12/27/18 20:50:09 (811) LogStatusMonitor.60 stats threads: 83, memory max: 952.0mb, allocated: 952.0mb, used: 888.0mb, standard.queued: 0 probes, standard.processing: 1 probes, expedited.queued: 0 probes, expedited.processing: 0 probes, interactive.queued: 0 probes, interactive.processing: 0 probes
12/27/18 20:51:39 (159) LogStatusMonitor.60 stats threads: 84, memory max: 952.0mb, allocated: 952.0mb, used: 887.0mb, standard.queued: 0 probes, standard.processing: 1 probes, expedited.queued: 0 probes, expedited.processing: 0 probes, interactive.queued: 0 probes, interactive.processing: 0 probes
12/27/18 20:51:42 (566) ECCSender.1 WARNING *** WARNING *** OutOfMemoryError: GC overhead limit exceeded
12/27/18 20:51:42 (566) ECCQueueMonitor.40 WARNING *** WARNING *** OutOfMemoryError: GC overhead limit exceeded
12/27/18 20:52:11 (670) WrapperStartStopAppMain Running under Java version: 1.8.0_152, java PID: 7680, args: start
12/27/18 20:52:11 (670) WrapperStartStopAppMain Initializing MID Server
12/27/18 20:52:11 (686) MIDServer Creating injector...
12/27/18 20:52:12 (045) MIDServer Using configuration: C:\Servicenow\disco_agent\config.xml
12/27/18 20:52:12 (249) MIDServer Logger config: root=INFO
12/27/18 20:52:12 (249) MIDServer Refreshing LoggerFactory cache
12/27/18 20:52:12 (483) MIDServer Loaded credentials provider: com.service_now.mid.keypairs.provider.standard.StandardKeyPairsProvider
12/27/18 20:52:12 (499) MIDServer ThreadPool-Interactive started with corePoolSize: 10, maxPoolSize: 10, maximumQueueSize: 40
12/27/18 20:52:12 (499) MIDServer ThreadPool-Expedited started with corePoolSize: 20, maxPoolSize: 20, maximumQueueSize: 400
12/27/18 20:52:12 (499) MIDServer ThreadPool-Standard started with corePoolSize: 25, maxPoolSize: 25, maximumQueueSize: 500
12/27/18 20:52:12 (499) MIDServer ExtensionContainer ThreadPool started with corePoolSize: 25, maximumPoolSize: 25, maximumQueueSize: 500
12/27/18 20:52:14 (858) MIDServer Setting basic authentication with user SNdiscovery
12/27/18 20:52:14 (874) MIDServer Using proxy host=172.20.170.7, port=8080, user=
12/27/18 20:52:15 (249) MIDServer MIDCredentialsConfigProvider initialized with com.service_now.mid.creds.provider.standard.StandardCredentialsProvider
12/27/18 20:52:15 (358) MIDServer MID Server starting
12/27/18 20:52:15 (421) MIDServer Agent home path: C:\Servicenow\disco_agent
12/27/18 20:52:15 (655) MIDServer MID Server started
12/27/18 20:52:16 (421) StartupSequencer Successfully connected to instance:
12/27/18 20:52:16 (421) StartupSequencer Install name: NGA - Production
12/27/18 20:52:16 (421) StartupSequencer Instance name: ngahr
12/27/18 20:52:16 (421) StartupSequencer Node: b8207c47db5e415c63155ef795da4225
12/27/18 20:52:16 (421) StartupSequencer Build date: 09-12-2018_0933
12/27/18 20:52:16 (421) StartupSequencer Build tag: glide-kingston-10-17-2017__patch9-09-05-2018
12/27/18 20:52:16 (421) StartupSequencer Instance ID: 3d3f87127d3300008e533b11f89a1652
12/27/18 20:52:16 (421) StartupSequencer System ID: app128019.ams7.service-now.com:ngahr074
12/27/18 20:52:16 (421) StartupSequencer Instance IP: 10.221.128.19
12/27/18 20:52:16 (421) StartupSequencer MID buildstamp: kingston-10-17-2017__patch9-09-05-2018_09-12-2018_0933
12/27/18 20:52:16 (686) StartupSequencer SOAP basic authentication is enabled
12/27/18 20:52:16 (686) StartupSequencer SOAP strict security is enabled
12/27/18 20:52:16 (686) StartupSequencer User SNdiscovery has all necessary roles
12/27/18 20:52:17 (155) StartupSequencer Getting instance ACLs for table: ecc_agent
12/27/18 20:52:18 (389) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
12/27/18 20:52:18 (389) StartupSequencer Waiting to retry in 5 minutes. Attempt 1 of 3.
12/27/18 20:57:18 (763) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
12/27/18 20:57:18 (763) StartupSequencer Waiting to retry in 5 minutes. Attempt 2 of 3.
12/27/18 21:02:19 (121) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
12/27/18 21:02:19 (121) StartupSequencer Waiting to retry in 5 minutes. Attempt 3 of 3.
12/27/18 21:07:19 (401) StartupSequencer WARNING *** WARNING *** Encountered error: [An active MID Server with a duplicate name detected.] in ensuring agent record on the instance. Retry...
12/27/18 21:07:19 (713) StartupSequencer Stopping MID Server due to exceeding retry attempts.
12/27/18 21:07:20 (729) Wrapper-Stopper Running under Java version: 1.8.0_152, java PID: 7680, args: stop
12/27/18 21:07:20 (729) Wrapper-Stopper Stopping MID server
12/27/18 21:07:20 (729) Wrapper-Stopper Destroying injector...
12/27/18 21:07:20 (729) Wrapper-Stopper Closing com.service_now.mid.amb.AMBClientProvider
12/27/18 21:07:20 (729) Wrapper-Stopper Closing com.service_now.monitor.PriorityThreadPoolProvider
12/27/18 21:07:20 (729) Wrapper-Stopper Shutting down ThreadPool-Interactive
12/27/18 21:07:20 (729) Wrapper-Stopper Shutting down ThreadPool-Expedited
12/27/18 21:07:20 (729) Wrapper-Stopper Shutting down ThreadPool-Standard
12/27/18 21:07:20 (729) Wrapper-Stopper ThreadPool-Interactive terminated
12/27/18 21:07:20 (729) Wrapper-Stopper ThreadPool-Expedited terminated
12/27/18 21:07:20 (729) Wrapper-Stopper ThreadPool-Standard terminated
12/27/18 21:07:20 (729) Wrapper-Stopper Closing com.service_now.mid.extension.container.ExtensionContainer
12/27/18 21:07:20 (729) Wrapper-Stopper ExtensionContainer is shutting down...
12/27/18 21:07:20 (729) Wrapper-Stopper ...waiting a maximum shutdown time of 1000ms
12/27/18 21:07:20 (729) Wrapper-Stopper ExtensionContainer is cleanly shut down
12/27/18 21:07:20 (729) Wrapper-Stopper Closing com.service_now.mid.probe.event.SNEventBulkSender
12/27/18 21:07:21 (026) EventBulkSenderThread-1 the event sender was stopped after sending 0 events in 0 bulks.
12/27/18 21:07:21 (026) Wrapper-Stopper Closing com.service_now.mid.cluster.ignite.IgniteClusterManager
12/27/18 21:07:21 (104) MIDServer MID Server stopping
12/27/18 21:07:21 (245) MIDServer Getting instance ACLs for table: ldap_server_config
12/27/18 21:07:21 (807) MIDServer Stoping LDAP Listener for: NGAHRUser
12/27/18 21:07:22 (073) MIDServer Stoping LDAP Listener for: Moorepay LDAP Servers
12/27/18 21:07:22 (307) MIDServer Stoping LDAP Listener for: RebusHR LDAP Servers
12/27/18 21:07:22 (651) MIDServer MID Server stopped

[moers]

Seems to be related to the way how the MID server is stoped. If you set the server manually to "Down" before the MID is stated, it just starts fine.

Guess the SIGTERM or SIGINT is not properly catchend to first sync the stop status with ServiceNow 

[JMV15]

Stumbled upon this issue, and found the solution and figured I would share as it was rather strange solution. The issue was the directory structure which apparently is what is set for mid_sys_id. For example:

I had 3 servers with a directory structure like this:

/opt/servicenow/mid/agent/<contents of extracted mid-london zip>

The mid server takes the directory "mid" and sets it as the mid_sys_id which was throwing the error above. 

By renaming the "mid" directory to something like the hostname, it was able to fix the issue:

SERVER 1 ==> /opt/servicenow/wpos-u1604/agent

SERVER 2 ==> /opt/servicenow/ospos-u1604/agent

SERVER 3 ==> /opt/servicenow/webapp-00/agent

Hope this helps 🙂