Frustration Obviation...

[SlightlyLoony]

There are times when installing a MID server can be very frustrating. Most of the time, you edit the config.xml file, start it up, and off it goes. Sometimes, though, the danged thing isn't so cooperative — that's when you feel like our tech with the tiny ears at right.

Generally speaking, the most frustrating thing is that you've got no idea what's going on. You look at the MID server log, and there's just no clue in there. Your only out is to pore over the config.xml file and the configuration on the instance, searching for something — anything — that might be wrong. Or chew on your keyboard, whichever feels better and is more effective.

Well get ready to celebrate, because those days are over, starting with the next release. No longer will you need to wash the foul taste of your keyboard from your mouth. Break out the champagne and start dancing on the tables!

I'm going to take you through a MID server installation where I have deliberately screwed up just about everything that could possibly be screwed up. You'll see how the MID server log now tell me exactly what's wrong.

So the first time I try running my messed-up MID server, here's what I see in the MID server log:

10/10/11 09:51:07 (792) main Running under Java version: 1.6.0_22
10/10/11 09:51:08 (346) main Initializing MID Server
10/10/11 09:51:08 (472) MIDServer MID Server starting
10/10/11 09:51:09 (125) MIDServer Using configuration: /glide/workspace/com.service_now.agent/work/config.xml
10/10/11 09:51:10 (252) MIDServer Agent home path: /glide/workspace/com.service_now.agent
10/10/11 09:51:10 (325) StartupSequencer Setting basic authentication with user mid_server
10/10/11 09:51:10 (357) MIDServer MID Server started
10/10/11 09:51:10 (676) StartupSequencer SEVERE *** ERROR *** Problem invoking InstanceInfo on http://localhost:8081/snc/: IOException: Connection refused

The MID server stops right there, knowing that it can do nothing further until this issue is rectified. It will retry once per minute, hoping that in the meantime you've fixed the problem. In my case, it's just a dumb little typo: I typed port 8081 instead of 8080. I fixed the typo and restarted the MID server so that it would re-read the config.xml file. This could have been any kind of connectivity problem, however — a bad URL, a missing proxy configuration, a firewall issue, etc. The MID server, unfortunately, can't tell exactly what caused the connectivity issue, but it certainly can tell you that it's having one. And now it does!

So I fixed that problem and ran it again. Now I see this in the MID server log:

10/10/11 09:52:22 (358) main Running under Java version: 1.6.0_22
10/10/11 09:52:22 (436) main Initializing MID Server
10/10/11 09:52:22 (540) MIDServer MID Server starting
10/10/11 09:52:22 (858) MIDServer Using configuration: /glide/workspace/com.service_now.agent/work/config.xml
10/10/11 09:52:23 (660) MIDServer Agent home path: /glide/workspace/com.service_now.agent
10/10/11 09:52:23 (677) StartupSequencer Setting basic authentication with user mid_server
10/10/11 09:52:23 (762) MIDServer MID Server started
10/10/11 09:52:24 (045) StartupSequencer Successfully connected to instance:
10/10/11 09:52:24 (045) StartupSequencer         Install name: Demo Server
10/10/11 09:52:24 (045) StartupSequencer       Instance name: unregistered
10/10/11 09:52:24 (045) StartupSequencer                         Node: 677dc85b774fe69066fea969f1780d52
10/10/11 09:52:24 (045) StartupSequencer             Build date: 10-08-2011_2100
10/10/11 09:52:24 (045) StartupSequencer               Build tag: glide-10-08-2011_2100
10/10/11 09:52:24 (045) StartupSequencer           Instance ID: b1020d20a7120000dadaefd459acf411
10/10/11 09:52:24 (046) StartupSequencer               System ID: slightlyloony.service-now.com:glide
10/10/11 09:52:24 (046) StartupSequencer           Instance IP: 10.1.0.99
10/10/11 09:52:24 (046) StartupSequencer           MID version: 10-04-2011_1946
10/10/11 09:52:24 (075) StartupSequencer WARNING *** WARNING *** Could not authenticate user 'mid_server' on the ServiceNow instance

Again, the MID server stops at this point, and retries once a minute. Note that this time it logged a bunch of information about the instance I connected to — the idea there is to give you the information needed to verify that you've configured it to talk to the correct instance. Somehow I accidentally got that right. But now I've got a pretty clear warning on the bottom: the MID server couldn't authenticate the user ("mid_server") that I put into config.xml. There are several possible causes: the user is missing, its password doesn't match what I put in the config.xml, the user is inactive, etc. In my case, I simply forgot the user. So I added it, and tried again:

10/10/11 09:59:36 (047) main Running under Java version: 1.6.0_22
10/10/11 09:59:36 (075) main Initializing MID Server
10/10/11 09:59:36 (179) MIDServer MID Server starting
10/10/11 09:59:36 (529) MIDServer Using configuration: /glide/workspace/com.service_now.agent/work/config.xml
10/10/11 09:59:37 (454) MIDServer Agent home path: /glide/workspace/com.service_now.agent
10/10/11 09:59:37 (470) StartupSequencer Setting basic authentication with user mid_server
10/10/11 09:59:37 (555) MIDServer MID Server started
10/10/11 09:59:37 (827) StartupSequencer Successfully connected to instance:
10/10/11 09:59:37 (850) StartupSequencer         Install name: Demo Server
10/10/11 09:59:37 (850) StartupSequencer       Instance name: unregistered
10/10/11 09:59:37 (850) StartupSequencer                         Node: 677dc85b774fe69066fea969f1780d52
10/10/11 09:59:37 (850) StartupSequencer             Build date: 10-08-2011_2100
10/10/11 09:59:37 (850) StartupSequencer               Build tag: glide-10-08-2011_2100
10/10/11 09:59:37 (850) StartupSequencer           Instance ID: b1020d20a7120000dadaefd459acf411
10/10/11 09:59:37 (850) StartupSequencer               System ID: slightlyloony.service-now.com:glide
10/10/11 09:59:37 (850) StartupSequencer           Instance IP: 10.1.0.99
10/10/11 09:59:37 (850) StartupSequencer           MID version: 10-04-2011_1946
10/10/11 09:59:37 (954) StartupSequencer SOAP basic authentication is enabled
10/10/11 09:59:37 (954) StartupSequencer SOAP strict security is enabled
10/10/11 09:59:37 (954) StartupSequencer WARNING *** WARNING *** Missing role from user mid_server: soap_ecc

Once again the MID server comes to a screeching halt, and will retry every minute until I get it right. What did I mess up this time? Well, I forgot to give my mid_server user the soap_ecc role, despite the documentation on the wiki that makes it abundantly clear that I should have. Sheesh, what a maroon! Fixed that, and tried again:

10/10/11 10:02:45 (065) main Running under Java version: 1.6.0_22
10/10/11 10:02:45 (108) main Initializing MID Server
10/10/11 10:02:45 (213) MIDServer MID Server starting
10/10/11 10:02:45 (482) MIDServer Using configuration: /glide/workspace/com.service_now.agent/work/config.xml
10/10/11 10:02:46 (290) MIDServer Agent home path: /glide/workspace/com.service_now.agent
10/10/11 10:02:46 (326) StartupSequencer Setting basic authentication with user mid_server
10/10/11 10:02:46 (393) MIDServer MID Server started
10/10/11 10:02:46 (660) StartupSequencer Successfully connected to instance:
10/10/11 09:02:46 (675) StartupSequencer         Install name: Demo Server
10/10/11 09:02:46 (675) StartupSequencer       Instance name: unregistered
10/10/11 09:02:46 (675) StartupSequencer                         Node: 677dc85b774fe69066fea969f1780d52
10/10/11 09:02:46 (675) StartupSequencer             Build date: 10-08-2011_2100
10/10/11 09:02:46 (675) StartupSequencer               Build tag: glide-10-08-2011_2100
10/10/11 09:02:46 (675) StartupSequencer           Instance ID: b1020d20a7120000dadaefd459acf411
10/10/11 09:02:46 (675) StartupSequencer               System ID: slightlyloony.service-now.com:glide
10/10/11 09:02:46 (675) StartupSequencer           Instance IP: 10.1.0.99
10/10/11 09:02:46 (675) StartupSequencer           MID version: 10-04-2011_1946
10/10/11 10:02:46 (751) StartupSequencer SOAP basic authentication is enabled
10/10/11 10:02:46 (751) StartupSequencer SOAP strict security is enabled
10/10/11 10:02:46 (751) StartupSequencer User mid_server has all necessary roles
10/10/11 10:02:46 (771) File sync worker: ecc_agent_mib Starting file synchronization: ecc_agent_mib
10/10/11 10:02:46 (787) StartupSequencer Enabling monitor: FileSyncer
10/10/11 10:02:46 (788) File sync worker: ecc_agent_jar Starting file synchronization: ecc_agent_jar
10/10/11 10:02:47 (001) File sync worker: ecc_agent_jar Finishing file synchronization: ecc_agent_jar
10/10/11 10:02:47 (001) File sync worker: ecc_agent_mib Finishing file synchronization: ecc_agent_mib
10/10/11 10:02:48 (838) StartupSequencer Getting instance ACLs for table: ecc_agent_property
10/10/11 10:02:49 (116) StartupSequencer Getting instance ACLs for table: ecc_agent
10/10/11 10:02:49 (167) StartupSequencer WARNING *** WARNING *** Can't read because table ACL denies it: ecc_agent

This time the MID server doesn't stop — it keeps going, as I've now got enough configured correctly that it can function, albeit with some kind of issue caused by its inability to get to the ecc_agent table. I know this because the warning is telling me that the ACL (Access Control List) is not letting the MID server read the ecc_agent table. Anytime there's a missing ACL (System Security → Access Control) you'll see one of these warnings in the log. The impact of the ACL issues varies depending on the table and the type of ACL (read, write, etc.) that's missing. But one thing you can be certain of: if you see one of these warnings, then the ACLs on the instance need to be fixed, or something on the MID server ain't a-gonna work correctly. So I added the missing ACL and ran again:

10/10/11 10:03:54 (119) main Running under Java version: 1.6.0_22
10/10/11 10:03:54 (336) main Initializing MID Server
10/10/11 10:03:54 (497) MIDServer MID Server starting
10/10/11 10:03:55 (067) MIDServer Using configuration: /glide/workspace/com.service_now.agent/work/config.xml
10/10/11 10:03:56 (303) MIDServer Agent home path: /glide/workspace/com.service_now.agent
10/10/11 10:03:56 (403) MIDServer MID Server started
10/10/11 10:03:56 (438) StartupSequencer Setting basic authentication with user mid_server
10/10/11 10:03:58 (798) StartupSequencer Successfully connected to instance:
10/10/11 10:03:58 (799) StartupSequencer         Install name: Demo Server
10/10/11 10:03:58 (799) StartupSequencer       Instance name: unregistered
10/10/11 10:03:58 (799) StartupSequencer                         Node: 677dc85b774fe69066fea969f1780d52
10/10/11 10:03:58 (799) StartupSequencer             Build date: Sun_Oct_09_12_24_01_PDT_2011
10/10/11 10:03:58 (799) StartupSequencer               Build tag:
10/10/11 10:03:58 (799) StartupSequencer           Instance ID: b1020d20a7120000dadaefd459acf411
10/10/11 10:03:58 (799) StartupSequencer               System ID: slightlyloony.dilatush.com:glide
10/10/11 10:03:58 (799) StartupSequencer           Instance IP: 10.179.0.99
10/10/11 10:03:58 (799) StartupSequencer           MID version: 10-04-2011_1946
10/10/11 10:03:59 (118) StartupSequencer SOAP basic authentication is enabled
10/10/11 10:03:59 (118) StartupSequencer SOAP strict security is enabled
10/10/11 10:03:59 (118) StartupSequencer User mid_server has all necessary roles
10/10/11 10:03:59 (298) File sync worker: ecc_agent_mib Starting file synchronization: ecc_agent_mib
10/10/11 10:03:59 (302) File sync worker: ecc_agent_jar Starting file synchronization: ecc_agent_jar
10/10/11 10:03:59 (308) StartupSequencer Enabling monitor: FileSyncer
10/10/11 10:04:00 (005) File sync worker: ecc_agent_jar Deleting /glide/workspace/com.service_now.agent/extlib/.cvsignore
10/10/11 10:04:00 (036) File sync worker: ecc_agent_jar Deleting directory /glide/workspace/com.service_now.agent/extlib/CVS and all directories and files it contains
10/10/11 10:04:00 (036) File sync worker: ecc_agent_mib Finishing file synchronization: ecc_agent_mib
10/10/11 10:04:00 (125) File sync worker: ecc_agent_jar Finishing file synchronization: ecc_agent_jar
10/10/11 10:04:01 (463) StartupSequencer Getting instance ACLs for table: ecc_agent_property
10/10/11 10:04:02 (387) StartupSequencer Getting instance ACLs for table: ecc_agent
10/10/11 10:04:02 (904) StartupSequencer Enabling monitor: RefreshMonitor
10/10/11 10:04:03 (191) StartupSequencer Enabling monitor: ECCQueueMonitor
10/10/11 10:04:03 (341) StartupSequencer Enabling monitor: ECCSender
10/10/11 10:04:03 (374) StartupSequencer Enabling monitor: LogStatusMonitor
10/10/11 10:04:03 (706) StartupSequencer Getting instance ACLs for table: ecc_queue
10/10/11 10:04:03 (952) StartupSequencer Enabling monitor: StatusMonitor
10/10/11 10:04:08 (486) StartupSequencer Loaded credentials provider: com.service_now.mid.creds.standard.StandardCredentialsProvider
10/10/11 10:04:09 (096) StartupSequencer Public SNMP Credentials loaded
10/10/11 10:04:09 (096) StartupSequencer Credentials from instance loaded
10/10/11 10:04:09 (576) MIB Initializer Loading MIBs
10/10/11 10:04:10 (751) StartupSequencer Getting instance ACLs for table: ecc_agent_script_include
10/10/11 10:04:12 (804) LogStatusMonitor.60 stats threads: 17, memory max: 263.0mb, allocated: 81.0mb, used: 5.0mb, queued: 0 probes, processing: 0 probes

Ah, now that's more like it! The MID server is up and running, with no reported problems. Woo hoo! That nasty-tasting keyboard is going in the trash!