Debug Techniques – Geofence synchronization deep dive

884
0
11-08-2019 05:22 PM
RJSunderman
Esri Regular Contributor
0 0 884

This blog is one in a series of blogs discussing debugging techniques you can use when working to identify the root cause of an issue with a GeoEvent Server deployment or configuration. Click any link in the quick list below to jump to another blog in the series.

 

In this blog I will discuss a technique I have used to perform a targeted extraction of debug messages being logged as GeoEvent Server queries a feature record set from an available polygon feature service to synchronize its geofences. The technique expands the use of command-line utilities first introduced in a previous blog. These utilities enable us to perform pattern matching on specific sections of a logged message then extract and apply string substitution and formatting to the logged messages, live, as the messages are being written, to make them easier to read.

A lot of the analysis I am about to demonstrate could be done using a static log file and a text editor, but I have come to really appreciate the power inherent in the command-line utilities I am covering in this blog. Our goal will be to find and review HTTP requests GeoEvent Server makes on a feature service resource being used as the authoritative source of area of interest polygons as well as the feature service's responses to the requests.

Scenario

A customer has published a feature service with several dozen polygons representing different areas of interest and configured a Geofence Synchronization Rule to enable the polygons to be periodically imported and synchronized to keep a set of geofences up-to-date. We know that GeoEvent Server polls the feature service to obtain a feature record set and registers the geometries with its AOI Manager – in this context AOI is short for "Area of Interest".

For this exercise we are interested in the interface between GeoEvent Server and an ArcGIS Server feature service, not the internal operations of the AOI Manager. We want to capture information on feature record requests and the responses to these requests. GeoEvent Manager does not provide an indication of when geofence synchronization occurs, only that it occurs once every 10 minutes in the customer's configuration, so the customer would like to know if enabling debug logging for a specific component logger will grant them additional visibility into the periodic geofence refresh as it takes place. Knowing when a synchronization is about to occur will more deterministic testing on the real-time analytics configured without resorting to aggressive synchronizations every few seconds.

Geofence Synchronization

To begin testing the scenario described above I published a feature service and added a few dozen polygon feature records to the service's feature data set. I can query the feature records via the feature service's REST endpoint:

Notice that each feature record has two attribute fields, gf_category and gf_name, which can be used to uniquely name and organize geofences when they are imported into GeoEvent Server.

Next, in GeoEvent Manager, I configure a synchronization rule that will query the feature service every 10 minutes. The feature records illustrated above will be loaded into the GeoEvent Server’s AOI Manager which handles the addition and update of geofences.

At this point I know that GeoEvent Server is periodically querying the feature service, but the GeoEvent Manager web application does not provide any indication of when the synchronizations will occur. I know the synchronization cycle starts when I click the Synchronize button and occurs every 10 minutes after that, but I do not know which component loggers would be most appropriate to watch for DEBUG messages. My only real choice, then, is to request debug logging for all component loggers by setting the level DEBUG on the ROOT component (knowing that this will cause the karaf.log file to grow very large very quickly).

In a previous blog, Application logging tips and tricks, I introduced tail and grep, a couple of command-line tools that can be used to help identify and isolate logged messages based on keywords or phrases. Using this technique to identify logged messages which include specific keywords allows me to focus on messages of particular interest.

In this case, however, using grep to search will not work as well because a pattern match may occur anywhere in a logged message's text. Using grep to look for something like MyGeofences[/]FeatureServer[/]0 to is likely to match more than we are interested in, specifically because the feature service’s URL appears in both the thread identifier as well as the actual message portion of numerous logged messages. So we need a more discriminating technique. We need a way to apply a regular expression pattern match to a specific portion of a logged message and associate a successful pattern match with an action we can run on the text of messages as they are written to the system’s log file.

Power tools for text processing and data extraction

Consider the following command which leverages awk rather than grep and a new stream editing utility sed:

rsunderman@localhost  //localhost/C$/Program Files/ArcGIS/Server/GeoEvent/data/log
tail -0f karaf.log | awk -F\| '$6 ~ /rest.*services.*MyGeofences/ { print $1 $4 $6; fflush() }' |sed 's/[&]token[=][0-9a-zA-Z_-]*/.../'

The awk command is typically used for data extraction and reporting. It is a text processing language developed by Aho, Weinberger, and Kernighan (yes, AWK is an acronym). The sed command is a stream editor used to filter and transform text. When interpreting the command line illustrated above remember that logged messages have six parts and each part is separated by a pipe ( | ) character.

Logged messages have six parts

As new messages are added to the karaf.log each message’s text is processed by the awk script which specifies that a pipe character should be used as the field delimiter and that the sixth field, the actual message, should match the specified regular expression pattern. If the pattern is matched then fields 1, 4, and 6 from each logged message are printed as output. The fflush( ) is important to force the command's buffered content to be flushed as each line of text is processed so that the sed command can identify a string of characters matching a query parameter &token= and replace the entire string with a few literal dots (simplifying the overall string).

There is a lot of power packed into this command. It enables us to apply a dynamic if / then evaluation to each logged message as the message is committed to the system log file, discard any message when a specific field does not match a specific pattern, and reformat messages on-the-fly to simplify their display. Wow.

You can read all about the power of sed and awk online. O’Reilly Media has an entire book dedicated to using sed and awk as power tools for text processing and data extraction.

Determining which component logger(s) to watch

The following illustration shows the output produced when the command above is used to filter the large volume of messages logged by all components when debug logging is requested at the ROOT level. For this example, assume that the command was run just before the Synchronize button is clicked to force a geofence synchronization rule to perform a set of queries against the feature service.

One pattern that stands out immediately is that there appear to be four requests made. Different component loggers represent these the requests in their own way, but we see key phrases repeated such as "Executing following request", "Main Client Exec ...Executing request" and the request's outgoing headers and actual request going out over the HTTP wire:


(Click to Enlarge Image)

We certainly don't need to see each request represented four different ways, and a quick search of the karaf.log for the key word "MainClientExec" shows the raw (unprocessed) log messages are associated with a particular class and bundle. These are clues to loggers we can interrogate further:

(Click to Enlarge Image)

If we are careful to leave DEBUG logging turned on at the ROOT level for only as long as it takes to navigate to the GeoFence Synchronization Rules and click Synchronize, then return to the Logs and change the settings back to WARN for the ROOT level, we can use the cached logged messages to generate a list of possible component loggers we might be interested in looking at more closely.

Two loggers that seem specifically appropriate are org.apache.http.impl.execchain.MainClientExec (because "MainClientExec" was identified as a class name of interest) and com.esri.ges.httpclient.Http (because the bundle identifier "com.esri.ges.framework.httpclient" was part of each logged message).

Requesting DEBUG logging on the HTTP Client logger will still produce a large number of logged messages. By targeting a single logger, however, we reduce the number of messages being logged overall; we are not interested in examining debug messages from the header or wire components for example. Also, we can tailor our sed and awk command to help further identify messages of particular interest. If we run our text extraction and format command on an active tail of the karaf.log – and take care to start and end the tail around the time that we navigate to GeoFence Synchronization Rules and click Synchronize – the number of logged messages is surprisingly manageable.

I have included the 24 lines extracted and formatted by the sample command below which is looking specifically for the key phrases "Executing request" and "Got response":

$ tail -0f karaf.log |awk -F\| '$6 ~ /(Executing request|Got response)/ { print $1 $6; fflush() }' |sed 's/[&]token[=][0-9a-zA-Z_-]*/.../'

 

2019-11-07T18:06:40,294  Executing request POST /arcgis/admin/machines/localhost/status HTTP/1.1
2019-11-07T18:06:40,342  Got response from HTTP request: <html lang="en">
2019-11-07T18:06:43,629  Executing request POST /arcgis/admin/system/configstore HTTP/1.1
2019-11-07T18:06:43,646  Got response from HTTP request: <html lang="en">
2019-11-07T18:06:46,622  Executing request GET /arcgis/help/en/geoevent HTTP/1.1
2019-11-07T18:06:46,626  Executing request GET /arcgis/help/en/geoevent/ HTTP/1.1
2019-11-07T18:06:47,250  Executing request GET /arcgis/rest/info?f=json HTTP/1.1
2019-11-07T18:06:47,253  Got response from HTTP request: {"currentVersion":10.8,"fullVersion":"10.8.0","soapUrl":"https://localhost:6443/arcgis/services","secureSoapUrl":null,"authInfo":{"isTokenBasedSecurity":true,"tokenServicesUrl":"https://localhost:6443/arcgis/tokens/","shortLivedTokenValidity":900}}.
2019-11-07T18:06:47,710  Executing request GET /arcgis/rest/services/?f=json..... HTTP/1.1
2019-11-07T18:06:47,720  Got response from HTTP request: {"currentVersion":10.8,"folders":["System","Utilities"],"services":[{"name":"AffectedTransLines-Buffers","type":"StreamServer"},{"name":"AffectedTransLines-Intersections","type":"StreamServer"},{"name":"CriticalInfrastructure","type":"FeatureServer"},{"name":"CriticalInfrastructure","type":"MapServer"},{"name":"Geofence_Stream","type":"StreamServer"},{"name":"MyGeofences","type":"FeatureServer"},{"name":"MyGeofences","type":"MapServer"},{"name":"SampleWorldCities","type":"MapServer"},{"name":"TropicalStormPolygons","type":"StreamServer"}]}.
2019-11-07T18:06:48,060  Executing request GET /arcgis/rest/services/?f=json..... HTTP/1.1
2019-11-07T18:06:48,068  Got response from HTTP request: {"currentVersion":10.8,"folders":["System","Utilities"],"services":[{"name":"AffectedTransLines-Buffers","type":"StreamServer"},{"name":"AffectedTransLines-Intersections","type":"StreamServer"},{"name":"CriticalInfrastructure","type":"FeatureServer"},{"name":"CriticalInfrastructure","type":"MapServer"},{"name":"Geofence_Stream","type":"StreamServer"},{"name":"MyGeofences","type":"FeatureServer"},{"name":"MyGeofences","type":"MapServer"},{"name":"SampleWorldCities","type":"MapServer"},{"name":"TropicalStormPolygons","type":"StreamServer"}]}.
2019-11-07T18:06:56,608  Executing request GET /arcgis/rest/services/MyGeofences/FeatureServer/0/query?f=json.....&where=1%3D1&outFields=gf_name%2Cgf_category&outSR=4326 HTTP/1.1
2019-11-07T18:06:56,635  Got response from HTTP request: {"objectIdFieldName":"objectid","globalIdFieldName":"","geometryType":"esriGeometryPolygon","spatialReference":{"wkid":4326,"latestWkid":4326},"fields":[{"name":"gf_name","alias":"gf_name","type":"esriFieldTypeString","length":50},{"name":"gf_category","alias":"gf_category","type":"esriFieldTypeString","length":50}],"features":[{"attributes":{"gf_name":"Alpha_003","gf_category":"Alpha"},"geometry":{"rings":[[[-120.252028,30.944518],[-119.784204,29.644623],[-120.566595,29.483390],[-121.447948,30.461197],[-121.275115,30.841066],[-120.252028,30.944518]]]}},{"attributes":{"gf_name":"Alpha_005","gf_category":"Alpha"},"geometry":{"rings":[[[-120.943999,33.487086],[-121.032831,32.575755],[-121.690575,31.901015],[-122.421752,32.119503],[-122.245335,33.447119],[-120.943999,33.487086]]]}},{"attributes":{"gf_name":"Alpha_006","gf_category":"Alpha"},"geometry":{"rings":[[[-122.691280,29.516679],[-123.226533,29.802332],[-122.749277,31.805495],[-122.429246,32.118518],[-122.421752,32.119503],[-121.690575,31.901015],[-121.275115,30.841066],[-121.447948,30.461197],[-122.691280,29.516679]]]}},{"attributes":{"gf_name":"Alpha_008","gf_category":"Alpha"},"geometry":{"rings":[[[-120.851764,33.649721],[-120.165423,33.593953],[-119.397317,32.932664],[-120.074747,32.236847],[-121.032831,32.575755],[-120.943999,33.487086],[-120.851764,33.649721]]]}},{"attributes":{"gf_name":"Alpha_010","gf_category":"Alpha"},"geometry":{"rings":[[[-116.132660,31.584451],[-116.047511,31.421341],[-115.681330,29.828279],[-116.996163,30.707680],[-116.957586,31.120668],[-116.132660,31.584451]]]}},{"attributes":{"gf_name":"Alpha_011","gf_category":"Alpha"},"geometry":{"rings":[[[-117.397404,29.178025],[-117.888219,29.222649],[-118.816738,30.272808],[-118.787736,30.371437],[-118.275610,30.321049],[-117.406325,29.315306],[-117.397404,29.178025]]]}},{"attributes":{"gf_name":"Alpha_013","gf_category":"Alpha"},"geometry":{"rings":[[[-118.461679,30.835274],[-118.017691,30.803414],[-118.017804,30.732340],[-118.275610,30.321049],[-118.787736,30.371437],[-118.830849,30.513622],[-118.712642,30.726205],[-118.461679,30.835274]]]}},{"attributes":{"gf_name":"Alpha_014","gf_category":"Alpha"},"geometry":{"rings":[[[-118.017804,30.732340],[-117.331629,29.805684],[-117.406325,29.315306],[-118.275610,30.321049],[-118.017804,30.732340]]]}},{"attributes":{"gf_name":"Alpha_018","gf_category":"Alpha"},"geometry":{"rings":[[[-118.291482,32.187915],[-118.236504,32.105900],[-118.461679,30.835274],[-118.712642,30.726205],[-118.910999,31.691403],[-118.291482,32.187915]]]}},{"attributes":{"gf_name":"Alpha_021","gf_category":"Alpha"},"geometry":{"rings":[[[-118.236504,32.105900],[-117.610715,31.368293],[-118.017691,30.803414],[-118.461679,30.835274],[-118.236504,32.105900]]]}},{"attributes":{"gf_name":"Alpha_022","gf_category":"Alpha"},"geometry":{"rings":[[[-118.415540,32.957686],[-118.306950,32.857367],[-118.241221,32.789177],[-118.291482,32.187915],[-118.910999,31.691403],[-119.764803,31.398264],[-120.074747,32.236847],[-119.397317,32.932664],[-118.415540,32.957686]]]}},{"attributes":{"gf_name":"Alpha_023","gf_category":"Alpha"},"geometry":{"rings":[[[-116.802682,34.081536],[-115.652745,33.453531],[-115.641477,32.336068],[-115.871176,32.188122],[-117.476538,32.953794],[-116.802682,34.081536]]]}},{"attributes":{"gf_name":"Alpha_024","gf_category":"Alpha"},"geometry":{"rings":[[[-122.562145,38.611239],[-122.186957,38.336612],[-122.195569,38.107073],[-123.151426,37.051286],[-122.951406,38.539622],[-122.562145,38.611239]]]}},{"attributes":{"gf_name":"Alpha_026","gf_category":"Alpha"},"geometry":{"rings":[[[-121.521585,38.401753],[-121.317484,37.884274],[-121.542840,36.899873],[-121.646568,36.833617],[-122.195569,38.107073],[-122.186957,38.336612],[-121.521585,38.401753]]]}},{"attributes":{"gf_name":"Alpha_028","gf_category":"Alpha"},"geometry":{"rings":[[[-122.340072,35.533098],[-121.150046,34.948623],[-120.851764,33.649721],[-120.943999,33.487086],[-122.245335,33.447119],[-122.980897,34.359173],[-122.340072,35.533098]]]}},{"attributes":{"gf_name":"Alpha_030","gf_category":"Alpha"},"geometry":{"rings":[[[-122.195569,38.107073],[-121.646568,36.833617],[-122.497375,35.977360],[-123.316198,36.487165],[-123.151426,37.051286],[-122.195569,38.107073]]]}},{"attributes":{"gf_name":"Alpha_033","gf_category":"Alpha"},"geometry":{"rings":[[[-120.462003,35.205002],[-119.434621,34.271019],[-120.165423,33.593953],[-120.851764,33.649721],[-121.150046,34.948623],[-120.462003,35.205002]]]}},{"attributes":{"gf_name":"Alpha_034","gf_category":"Alpha"},"geometry":{"rings":[[[-120.314583,38.136693],[-119.722418,38.072922],[-120.702231,36.942569],[-121.542840,36.899873],[-121.317484,37.884274],[-120.314583,38.136693]]]}},{"attributes":{"gf_name":"Alpha_036","gf_category":"Alpha"},"geometry":{"rings":[[[-121.315802,38.800687],[-120.314583,38.136693],[-121.317484,37.884274],[-121.521585,38.401753],[-121.315802,38.800687]]]}},{"attributes":{"gf_name":"Alpha_038","gf_category":"Alpha"},"geometry":{"rings":[[[-117.414676,35.037767],[-116.873703,34.464625],[-116.878218,34.445776],[-117.452834,34.349222],[-117.874553,34.354357],[-117.900979,34.521991],[-117.414676,35.037767]]]}},{"attributes":{"gf_name":"Alpha_039","gf_category":"Alpha"},"geometry":{"rings":[[[-118.276782,35.277533],[-118.210805,35.269057],[-118.075170,35.188227],[-117.900979,34.521991],[-117.874553,34.354357],[-118.597699,33.869008],[-118.895173,34.292433],[-118.827343,34.677451],[-118.276782,35.277533]]]}},{"attributes":{"gf_name":"Alpha_041","gf_category":"Alpha"},"geometry":{"rings":[[[-119.837637,35.784433],[-118.827343,34.677451],[-118.895173,34.292433],[-119.434621,34.271019],[-120.462003,35.205002],[-119.837637,35.784433]]]}},{"attributes":{"gf_name":"Alpha_042","gf_category":"Alpha"},"geometry":{"rings":[[[-117.922812,36.598206],[-117.057992,36.394203],[-118.210805,35.269057],[-118.276782,35.277533],[-118.493063,35.699818],[-118.285579,36.557670],[-117.922812,36.598206]]]}},{"attributes":{"gf_name":"Alpha_043","gf_category":"Alpha"},"geometry":{"rings":[[[-118.075170,35.188227],[-117.434176,35.060678],[-117.414676,35.037767],[-117.900979,34.521991],[-118.075170,35.188227]]]}},{"attributes":{"gf_name":"Alpha_045","gf_category":"Alpha"},"geometry":{"rings":[[[-119.400803,37.662407],[-118.363534,37.428185],[-118.320407,36.580012],[-119.191764,36.798038],[-119.400803,37.662407]]]}},{"attributes":{"gf_name":"Alpha_046","gf_category":"Alpha"},"geometry":{"rings":[[[-119.629592,38.114023],[-119.400803,37.662407],[-119.191764,36.798038],[-119.814395,36.016233],[-120.702231,36.942569],[-119.722418,38.072922],[-119.629592,38.114023]]]}},{"attributes":{"gf_name":"Alpha_049","gf_category":"Alpha"},"geometry":{"rings":[[[-118.645011,38.788713],[-116.375726,38.414554],[-117.879285,37.762548],[-117.981593,37.812142],[-118.645011,38.788713]]]}},{"attributes":{"gf_name":"Alpha_050","gf_category":"Alpha"},"geometry":{"rings":[[[-117.981593,37.812142],[-117.879285,37.762548],[-117.850493,37.692040],[-117.922812,36.598206],[-118.285579,36.557670],[-118.320407,36.580012],[-118.363534,37.428185],[-117.981593,37.812142]]]}},{"attributes":{"gf_name":"Bravo_003","gf_category":"Bravo"},"geometry":{"rings":[[[-114.966407,29.010553],[-115.556070,29.010613],[-115.565899,29.576853],[-114.877388,30.652564],[-113.973903,31.144828],[-113.874728,31.024001],[-114.966407,29.010553]]]}},{"attributes":{"gf_name":"Bravo_004","gf_category":"Bravo"},"geometry":{"rings":[[[-116.047511,31.421341],[-114.877388,30.652564],[-115.565899,29.576853],[-115.681330,29.828279],[-116.047511,31.421341]]]}},{"attributes":{"gf_name":"Bravo_005","gf_category":"Bravo"},"geometry":{"rings":[[[-113.665880,33.089569],[-113.578775,33.084994],[-113.595481,32.109917],[-113.642988,31.702545],[-113.997771,31.250836],[-115.038456,32.239077],[-114.828726,32.423734],[-113.665880,33.089569]]]}},{"attributes":{"gf_name":"Bravo_007","gf_category":"Bravo"},"geometry":{"rings":[[[-116.842159,36.261753],[-116.346604,35.977788],[-116.271652,35.913982],[-116.010855,34.931918],[-116.723780,34.610674],[-116.842159,36.261753]]]}},{"attributes":{"gf_name":"Bravo_009","gf_category":"Bravo"},"geometry":{"rings":[[[-115.760073,34.464355],[-115.288817,34.426023],[-115.232718,33.750965],[-115.651894,33.454681],[-115.760073,34.464355]]]}},{"attributes":{"gf_name":"Bravo_012","gf_category":"Bravo"},"geometry":{"rings":[[[-112.309934,34.738007],[-111.899280,34.156477],[-111.896265,34.000485],[-112.259220,33.812066],[-112.559940,33.882035],[-112.785387,34.665098],[-112.309934,34.738007]]]}},{"attributes":{"gf_name":"Bravo_013","gf_category":"Bravo"},"geometry":{"rings":[[[-113.866163,31.017642],[-112.821893,30.803882],[-112.208051,30.141331],[-112.201103,29.892425],[-113.605198,29.548920],[-113.866163,31.017642]]]}},{"attributes":{"gf_name":"Bravo_014","gf_category":"Bravo"},"geometry":{"rings":[[[-111.159012,32.522856],[-110.824649,32.494792],[-110.141501,31.918549],[-110.403977,31.052692],[-111.259674,30.945511],[-111.315692,30.965117],[-111.474622,31.590875],[-111.467117,31.957874],[-111.159012,32.522856]]]}},{"attributes":{"gf_name":"Bravo_016","gf_category":"Bravo"},"geometry":{"rings":[[[-113.946703,29.010449],[-114.966407,29.010553],[-113.874728,31.024001],[-113.866163,31.017642],[-113.605198,29.548920],[-113.946703,29.010449]]]}},{"attributes":{"gf_name":"Bravo_018","gf_category":"Bravo"},"geometry":{"rings":[[[-112.935806,32.530579],[-112.905623,32.022493],[-113.642988,31.702545],[-113.595481,32.109917],[-112.935806,32.530579]]]}},{"attributes":{"gf_name":"Bravo_019","gf_category":"Bravo"},"geometry":{"rings":[[[-111.317819,34.348952],[-110.978438,33.833734],[-111.375070,33.198857],[-111.896265,34.000485],[-111.899280,34.156477],[-111.317819,34.348952]]]}},{"attributes":{"gf_name":"Bravo_020","gf_category":"Bravo"},"geometry":{"rings":[[[-112.909116,33.056288],[-112.454372,32.971595],[-112.423551,31.937676],[-112.551553,31.875448],[-112.905623,32.022493],[-112.935806,32.530579],[-112.909116,33.056288]]]}},{"attributes":{"gf_name":"Bravo_021","gf_category":"Bravo"},"geometry":{"rings":[[[-112.150814,33.001880],[-111.414706,32.914951],[-111.159012,32.522856],[-111.467117,31.957874],[-112.423551,31.937676],[-112.454372,32.971595],[-112.150814,33.001880]]]}},{"attributes":{"gf_name":"Bravo_022","gf_category":"Bravo"},"geometry":{"rings":[[[-114.546436,34.566336],[-114.000237,34.215944],[-114.203561,33.611652],[-114.485905,33.625307],[-114.892467,33.864714],[-114.546436,34.566336]]]}},{"attributes":{"gf_name":"Bravo_028","gf_category":"Bravo"},"geometry":{"rings":[[[-116.878218,34.445776],[-116.802682,34.081536],[-117.476538,32.953794],[-118.241221,32.789177],[-118.306950,32.857367],[-117.452834,34.349222],[-116.878218,34.445776]]]}},{"attributes":{"gf_name":"Bravo_029","gf_category":"Bravo"},"geometry":{"rings":[[[-116.010855,34.931918],[-115.974970,34.925304],[-115.760073,34.464355],[-115.651894,33.454681],[-115.652745,33.453531],[-116.802682,34.081536],[-116.878218,34.445776],[-116.873703,34.464625],[-116.723780,34.610674],[-116.010855,34.931918]]]}},{"attributes":{"gf_name":"Bravo_035","gf_category":"Bravo"},"geometry":{"rings":[[[-113.322646,36.492659],[-112.866662,35.823773],[-113.157328,34.983246],[-113.614524,35.263022],[-113.911112,36.188262],[-113.322646,36.492659]]]}},{"attributes":{"gf_name":"Bravo_037","gf_category":"Bravo"},"geometry":{"rings":[[[-115.337130,36.999392],[-114.286610,36.369889],[-114.190413,36.202457],[-114.581011,35.827259],[-114.984871,35.568119],[-115.038457,35.629228],[-115.332937,36.457187],[-115.360534,36.658888],[-115.337130,36.999392]]]}},{"attributes":{"gf_name":"Bravo_039","gf_category":"Bravo"},"geometry":{"rings":[[[-114.581011,35.827259],[-113.881352,35.215058],[-114.599067,34.811896],[-114.604860,34.809841],[-114.934130,35.107656],[-115.025696,35.248019],[-114.984871,35.568119],[-114.581011,35.827259]]]}},{"attributes":{"gf_name":"Bravo_040","gf_category":"Bravo"},"geometry":{"rings":[[[-115.635838,37.895516],[-114.244290,37.688867],[-114.286610,36.369889],[-115.337130,36.999392],[-115.635838,37.895516]]]}},{"attributes":{"gf_name":"Bravo_041","gf_category":"Bravo"},"geometry":{"rings":[[[-116.236850,38.430295],[-115.893363,38.243036],[-115.830905,38.042138],[-116.762045,36.853773],[-117.850493,37.692040],[-117.879285,37.762548],[-116.375726,38.414554],[-116.236850,38.430295]]]}},{"attributes":{"gf_name":"Bravo_043","gf_category":"Bravo"},"geometry":{"rings":[[[-113.032255,37.207939],[-112.165492,36.820693],[-111.999148,36.398822],[-112.273275,35.883587],[-112.866662,35.823773],[-113.322646,36.492659],[-113.032255,37.207939]]]}},{"attributes":{"gf_name":"Bravo_044","gf_category":"Bravo"},"geometry":{"rings":[[[-113.614524,35.263022],[-113.157328,34.983246],[-113.059816,34.730975],[-113.114472,34.672716],[-114.599067,34.811896],[-113.881352,35.215058],[-113.614524,35.263022]]]}},{"attributes":{"gf_name":"Bravo_045","gf_category":"Bravo"},"geometry":{"rings":[[[-113.372466,34.311458],[-113.327958,33.182361],[-113.578775,33.084994],[-113.665880,33.089569],[-114.203561,33.611652],[-114.000237,34.215944],[-113.372466,34.311458]]]}},{"attributes":{"gf_name":"Bravo_046","gf_category":"Bravo"},"geometry":{"rings":[[[-112.273275,35.883587],[-111.846116,35.154557],[-112.309934,34.738007],[-112.785387,34.665098],[-113.059816,34.730975],[-113.157328,34.983246],[-112.866662,35.823773],[-112.273275,35.883587]]]}},{"attributes":{"gf_name":"Bravo_047","gf_category":"Bravo"},"geometry":{"rings":[[[-111.265839,37.278314],[-111.175263,37.246313],[-110.752701,36.701053],[-110.999562,36.098601],[-111.999148,36.398822],[-112.165492,36.820693],[-111.896582,37.016041],[-111.265839,37.278314]]]}},{"attributes":{"gf_name":"Charlie_004","gf_category":"Charlie"},"geometry":{"rings":[[[-111.990476,39.623930],[-111.672383,39.412941],[-111.919637,38.212856],[-111.999787,38.197742],[-112.565550,38.183798],[-112.769221,38.858292],[-112.622809,39.071739],[-111.990476,39.623930]]]}},{"attributes":{"gf_name":"Charlie_005","gf_category":"Charlie"},"geometry":{"rings":[[[-112.811170,38.874945],[-112.769221,38.858292],[-112.565550,38.183798],[-113.120292,37.481661],[-113.857748,37.760542],[-113.852376,37.928864],[-113.462539,38.716036],[-112.811170,38.874945]]]}},{"attributes":{"gf_name":"Charlie_007","gf_category":"Charlie"},"geometry":{"rings":[[[-111.919637,38.212856],[-111.687861,38.152417],[-111.265839,37.278314],[-111.896582,37.016041],[-111.999787,38.197742],[-111.919637,38.212856]]]}},{"attributes":{"gf_name":"Charlie_008","gf_category":"Charlie"},"geometry":{"rings":[[[-111.315692,30.965117],[-111.259674,30.945511],[-110.796944,30.198316],[-110.956477,29.722505],[-112.072384,29.643578],[-112.201103,29.892425],[-112.208051,30.141331],[-111.315692,30.965117]]]}},{"attributes":{"gf_name":"Charlie_009","gf_category":"Charlie"},"geometry":{"rings":[[[-110.141501,31.918549],[-109.185745,31.877346],[-108.663232,31.118540],[-108.398365,30.600397],[-108.351497,29.968889],[-109.843830,30.505716],[-110.403977,31.052692],[-110.141501,31.918549]]]}},{"attributes":{"gf_name":"Charlie_012","gf_category":"Charlie"},"geometry":{"rings":[[[-110.403977,31.052692],[-109.843830,30.505716],[-110.466160,30.249463],[-110.796944,30.198316],[-111.259674,30.945511],[-110.403977,31.052692]]]}},{"attributes":{"gf_name":"Charlie_016","gf_category":"Charlie"},"geometry":{"rings":[[[-111.251511,38.338078],[-110.907121,38.232546],[-110.744795,37.758057],[-111.175263,37.246313],[-111.265839,37.278314],[-111.687861,38.152417],[-111.251511,38.338078]]]}},{"attributes":{"gf_name":"Charlie_017","gf_category":"Charlie"},"geometry":{"rings":[[[-110.848814,35.410481],[-110.395022,35.218355],[-110.629724,33.983079],[-110.978438,33.833734],[-111.317819,34.348952],[-111.227231,35.202718],[-110.848814,35.410481]]]}},{"attributes":{"gf_name":"Charlie_018","gf_category":"Charlie"},"geometry":{"rings":[[[-108.957760,35.823204],[-108.582120,34.448969],[-108.695642,34.413530],[-109.616894,35.160616],[-109.861048,35.391741],[-109.580750,35.671064],[-108.957760,35.823204]]]}},{"attributes":{"gf_name":"Charlie_019","gf_category":"Charlie"},"geometry":{"rings":[[[-109.616894,35.160616],[-108.695642,34.413530],[-109.209776,34.009453],[-109.616894,35.160616]]]}},{"attributes":{"gf_name":"Charlie_020","gf_category":"Charlie"},"geometry":{"rings":[[[-109.580423,33.485896],[-109.019515,32.893275],[-109.185745,31.877346],[-110.141501,31.918549],[-110.824649,32.494792],[-109.600599,33.481973],[-109.580423,33.485896]]]}},{"attributes":{"gf_name":"Charlie_026","gf_category":"Charlie"},"geometry":{"rings":[[[-107.448109,32.465305],[-107.543777,31.824440],[-108.398365,30.600397],[-108.663232,31.118540],[-108.172089,32.338211],[-107.448109,32.465305]]]}},{"attributes":{"gf_name":"Charlie_027","gf_category":"Charlie"},"geometry":{"rings":[[[-107.000647,33.131979],[-106.927124,33.119847],[-105.707650,32.307470],[-105.776106,31.834468],[-105.924658,31.432486],[-106.583294,31.970314],[-107.000647,33.131979]]]}},{"attributes":{"gf_name":"Charlie_028","gf_category":"Charlie"},"geometry":{"rings":[[[-106.583294,31.970314],[-105.924658,31.432486],[-105.907446,31.138703],[-106.150128,30.782825],[-107.095091,31.764133],[-106.583294,31.970314]]]}},{"attributes":{"gf_name":"Charlie_029","gf_category":"Charlie"},"geometry":{"rings":[[[-107.359704,33.554365],[-107.142280,33.201815],[-107.448109,32.465305],[-108.172089,32.338211],[-108.685156,32.962142],[-107.359704,33.554365]]]}},{"attributes":{"gf_name":"Charlie_030","gf_category":"Charlie"},"geometry":{"rings":[[[-105.994738,33.337477],[-105.436816,32.627620],[-105.422219,32.568667],[-105.707650,32.307470],[-106.927124,33.119847],[-105.994738,33.337477]]]}},{"attributes":{"gf_name":"Charlie_034","gf_category":"Charlie"},"geometry":{"rings":[[[-105.313424,33.867144],[-105.436816,32.627620],[-105.994738,33.337477],[-105.313424,33.867144]]]}},{"attributes":{"gf_name":"Charlie_036","gf_category":"Charlie"},"geometry":{"rings":[[[-110.055886,36.915457],[-110.000338,36.888631],[-109.580750,35.671064],[-109.861048,35.391741],[-110.224385,35.222138],[-110.395022,35.218355],[-110.848814,35.410481],[-110.999562,36.098601],[-110.752701,36.701053],[-110.055886,36.915457]]]}},{"attributes":{"gf_name":"Charlie_039","gf_category":"Charlie"},"geometry":{"rings":[[[-109.580447,36.961026],[-108.825944,35.920920],[-108.957760,35.823204],[-109.580750,35.671064],[-110.000338,36.888631],[-109.580447,36.961026]]]}},{"attributes":{"gf_name":"Charlie_040","gf_category":"Charlie"},"geometry":{"rings":[[[-108.381504,36.137964],[-106.993809,34.882178],[-107.053820,34.603020],[-107.376441,34.146431],[-108.254492,34.413094],[-108.396412,36.127488],[-108.381504,36.137964]]]}},{"attributes":{"gf_name":"Charlie_043","gf_category":"Charlie"},"geometry":{"rings":[[[-109.532017,37.942050],[-109.235501,37.903205],[-109.059044,37.837445],[-108.846176,37.328161],[-109.580447,36.961026],[-110.000338,36.888631],[-110.055886,36.915457],[-110.093643,37.604001],[-109.532017,37.942050]]]}},{"attributes":{"gf_name":"Charlie_045","gf_category":"Charlie"},"geometry":{"rings":[[[-110.295214,38.567151],[-110.205307,37.706183],[-110.744795,37.758057],[-110.907121,38.232546],[-110.295214,38.567151]]]}},{"attributes":{"gf_name":"Charlie_046","gf_category":"Charlie"},"geometry":{"rings":[[[-111.672383,39.412941],[-111.040607,39.348197],[-111.251511,38.338078],[-111.687861,38.152417],[-111.919637,38.212856],[-111.672383,39.412941]]]}},{"attributes":{"gf_name":"Charlie_047","gf_category":"Charlie"},"geometry":{"rings":[[[-108.586684,38.599815],[-107.751418,38.385245],[-107.882355,37.022654],[-108.096641,36.914409],[-108.846176,37.328161],[-109.059044,37.837445],[-108.586684,38.599815]]]}},{"attributes":{"gf_name":"Charlie_049","gf_category":"Charlie"},"geometry":{"rings":[[[-110.089960,38.906828],[-109.532017,37.942050],[-110.093643,37.604001],[-110.205307,37.706183],[-110.295214,38.567151],[-110.089960,38.906828]]]}},{"attributes":{"gf_name":"Charlie_050","gf_category":"Charlie"},"geometry":{"rings":[[[-109.171210,39.584714],[-108.586684,38.599815],[-109.059044,37.837445],[-109.235501,37.903205],[-109.527535,39.304970],[-109.171210,39.584714]]]}}]}.
2019-11-07T18:06:56,895  Executing request GET /arcgis/rest/services/MyGeofences/FeatureServer/0/query?f=json.....&where=1%3D1&outFields=gf_name%2Cgf_category&outSR=4326&returnIdsOnly=true HTTP/1.1
2019-11-07T18:06:56,906  Got response from HTTP request: {"objectIdFieldName":"objectid","objectIds":[3,5,6,8,10,11,13,14,18,21,22,23,24,26,28,30,33,34,36,38,39,41,42,43,45,46,49,50,53,54,55,57,59,62,63,64,66,68,69,70,71,72,78,79,85,87,89,90,91,93,94,95,96,97,104,105,107,108,109,112,116,117,118,119,120,126,127,128,129,130,134,136,139,140,143,145,146,147,149,150]}.
2019-11-07T18:06:57,294  Executing request GET /arcgis/rest/services/MyGeofences/FeatureServer/0/query?f=json.....&where=1%3D1&outFields=objectid%2Cgf_name%2Cgf_category&returnGeometry=false HTTP/1.1
2019-11-07T18:06:57,305  Got response from HTTP request: {"objectIdFieldName":"objectid","globalIdFieldName":"","geometryType":"esriGeometryPolygon","spatialReference":{"wkid":4326,"latestWkid":4326},"fields":[{"name":"objectid","alias":"OBJECTID","type":"esriFieldTypeOID"},{"name":"gf_name","alias":"gf_name","type":"esriFieldTypeString","length":50},{"name":"gf_category","alias":"gf_category","type":"esriFieldTypeString","length":50}],"features":[{"attributes":{"objectid":3,"gf_name":"Alpha_003","gf_category":"Alpha"}},{"attributes":{"objectid":5,"gf_name":"Alpha_005","gf_category":"Alpha"}},{"attributes":{"objectid":6,"gf_name":"Alpha_006","gf_category":"Alpha"}},{"attributes":{"objectid":8,"gf_name":"Alpha_008","gf_category":"Alpha"}},{"attributes":{"objectid":10,"gf_name":"Alpha_010","gf_category":"Alpha"}},{"attributes":{"objectid":11,"gf_name":"Alpha_011","gf_category":"Alpha"}},{"attributes":{"objectid":13,"gf_name":"Alpha_013","gf_category":"Alpha"}},{"attributes":{"objectid":14,"gf_name":"Alpha_014","gf_category":"Alpha"}},{"attributes":{"objectid":18,"gf_name":"Alpha_018","gf_category":"Alpha"}},{"attributes":{"objectid":21,"gf_name":"Alpha_021","gf_category":"Alpha"}},{"attributes":{"objectid":22,"gf_name":"Alpha_022","gf_category":"Alpha"}},{"attributes":{"objectid":23,"gf_name":"Alpha_023","gf_category":"Alpha"}},{"attributes":{"objectid":24,"gf_name":"Alpha_024","gf_category":"Alpha"}},{"attributes":{"objectid":26,"gf_name":"Alpha_026","gf_category":"Alpha"}},{"attributes":{"objectid":28,"gf_name":"Alpha_028","gf_category":"Alpha"}},{"attributes":{"objectid":30,"gf_name":"Alpha_030","gf_category":"Alpha"}},{"attributes":{"objectid":33,"gf_name":"Alpha_033","gf_category":"Alpha"}},{"attributes":{"objectid":34,"gf_name":"Alpha_034","gf_category":"Alpha"}},{"attributes":{"objectid":36,"gf_name":"Alpha_036","gf_category":"Alpha"}},{"attributes":{"objectid":38,"gf_name":"Alpha_038","gf_category":"Alpha"}},{"attributes":{"objectid":39,"gf_name":"Alpha_039","gf_category":"Alpha"}},{"attributes":{"objectid":41,"gf_name":"Alpha_041","gf_category":"Alpha"}},{"attributes":{"objectid":42,"gf_name":"Alpha_042","gf_category":"Alpha"}},{"attributes":{"objectid":43,"gf_name":"Alpha_043","gf_category":"Alpha"}},{"attributes":{"objectid":45,"gf_name":"Alpha_045","gf_category":"Alpha"}},{"attributes":{"objectid":46,"gf_name":"Alpha_046","gf_category":"Alpha"}},{"attributes":{"objectid":49,"gf_name":"Alpha_049","gf_category":"Alpha"}},{"attributes":{"objectid":50,"gf_name":"Alpha_050","gf_category":"Alpha"}},{"attributes":{"objectid":53,"gf_name":"Bravo_003","gf_category":"Bravo"}},{"attributes":{"objectid":54,"gf_name":"Bravo_004","gf_category":"Bravo"}},{"attributes":{"objectid":55,"gf_name":"Bravo_005","gf_category":"Bravo"}},{"attributes":{"objectid":57,"gf_name":"Bravo_007","gf_category":"Bravo"}},{"attributes":{"objectid":59,"gf_name":"Bravo_009","gf_category":"Bravo"}},{"attributes":{"objectid":62,"gf_name":"Bravo_012","gf_category":"Bravo"}},{"attributes":{"objectid":63,"gf_name":"Bravo_013","gf_category":"Bravo"}},{"attributes":{"objectid":64,"gf_name":"Bravo_014","gf_category":"Bravo"}},{"attributes":{"objectid":66,"gf_name":"Bravo_016","gf_category":"Bravo"}},{"attributes":{"objectid":68,"gf_name":"Bravo_018","gf_category":"Bravo"}},{"attributes":{"objectid":69,"gf_name":"Bravo_019","gf_category":"Bravo"}},{"attributes":{"objectid":70,"gf_name":"Bravo_020","gf_category":"Bravo"}},{"attributes":{"objectid":71,"gf_name":"Bravo_021","gf_category":"Bravo"}},{"attributes":{"objectid":72,"gf_name":"Bravo_022","gf_category":"Bravo"}},{"attributes":{"objectid":78,"gf_name":"Bravo_028","gf_category":"Bravo"}},{"attributes":{"objectid":79,"gf_name":"Bravo_029","gf_category":"Bravo"}},{"attributes":{"objectid":85,"gf_name":"Bravo_035","gf_category":"Bravo"}},{"attributes":{"objectid":87,"gf_name":"Bravo_037","gf_category":"Bravo"}},{"attributes":{"objectid":89,"gf_name":"Bravo_039","gf_category":"Bravo"}},{"attributes":{"objectid":90,"gf_name":"Bravo_040","gf_category":"Bravo"}},{"attributes":{"objectid":91,"gf_name":"Bravo_041","gf_category":"Bravo"}},{"attributes":{"objectid":93,"gf_name":"Bravo_043","gf_category":"Bravo"}},{"attributes":{"objectid":94,"gf_name":"Bravo_044","gf_category":"Bravo"}},{"attributes":{"objectid":95,"gf_name":"Bravo_045","gf_category":"Bravo"}},{"attributes":{"objectid":96,"gf_name":"Bravo_046","gf_category":"Bravo"}},{"attributes":{"objectid":97,"gf_name":"Bravo_047","gf_category":"Bravo"}},{"attributes":{"objectid":104,"gf_name":"Charlie_004","gf_category":"Charlie"}},{"attributes":{"objectid":105,"gf_name":"Charlie_005","gf_category":"Charlie"}},{"attributes":{"objectid":107,"gf_name":"Charlie_007","gf_category":"Charlie"}},{"attributes":{"objectid":108,"gf_name":"Charlie_008","gf_category":"Charlie"}},{"attributes":{"objectid":109,"gf_name":"Charlie_009","gf_category":"Charlie"}},{"attributes":{"objectid":112,"gf_name":"Charlie_012","gf_category":"Charlie"}},{"attributes":{"objectid":116,"gf_name":"Charlie_016","gf_category":"Charlie"}},{"attributes":{"objectid":117,"gf_name":"Charlie_017","gf_category":"Charlie"}},{"attributes":{"objectid":118,"gf_name":"Charlie_018","gf_category":"Charlie"}},{"attributes":{"objectid":119,"gf_name":"Charlie_019","gf_category":"Charlie"}},{"attributes":{"objectid":120,"gf_name":"Charlie_020","gf_category":"Charlie"}},{"attributes":{"objectid":126,"gf_name":"Charlie_026","gf_category":"Charlie"}},{"attributes":{"objectid":127,"gf_name":"Charlie_027","gf_category":"Charlie"}},{"attributes":{"objectid":128,"gf_name":"Charlie_028","gf_category":"Charlie"}},{"attributes":{"objectid":129,"gf_name":"Charlie_029","gf_category":"Charlie"}},{"attributes":{"objectid":130,"gf_name":"Charlie_030","gf_category":"Charlie"}},{"attributes":{"objectid":134,"gf_name":"Charlie_034","gf_category":"Charlie"}},{"attributes":{"objectid":136,"gf_name":"Charlie_036","gf_category":"Charlie"}},{"attributes":{"objectid":139,"gf_name":"Charlie_039","gf_category":"Charlie"}},{"attributes":{"objectid":140,"gf_name":"Charlie_040","gf_category":"Charlie"}},{"attributes":{"objectid":143,"gf_name":"Charlie_043","gf_category":"Charlie"}},{"attributes":{"objectid":145,"gf_name":"Charlie_045","gf_category":"Charlie"}},{"attributes":{"objectid":146,"gf_name":"Charlie_046","gf_category":"Charlie"}},{"attributes":{"objectid":147,"gf_name":"Charlie_047","gf_category":"Charlie"}},{"attributes":{"objectid":149,"gf_name":"Charlie_049","gf_category":"Charlie"}},{"attributes":{"objectid":150,"gf_name":"Charlie_050","gf_category":"Charlie"}}]}.
2019-11-07T18:06:57,563  Executing request GET /arcgis/rest/services/MyGeofences/FeatureServer/0/query?f=json.....&where=1%3D1&outFields=objectid%2Cgf_name%2Cgf_category&returnGeometry=false&returnIdsOnly=true HTTP/1.1
2019-11-07T18:06:57,573  Got response from HTTP request: {"objectIdFieldName":"objectid","objectIds":[3,5,6,8,10,11,13,14,18,21,22,23,24,26,28,30,33,34,36,38,39,41,42,43,45,46,49,50,53,54,55,57,59,62,63,64,66,68,69,70,71,72,78,79,85,87,89,90,91,93,94,95,96,97,104,105,107,108,109,112,116,117,118,119,120,126,127,128,129,130,134,136,139,140,143,145,146,147,149,150]}.
2019-11-07T18:07:00,360  Executing request POST /arcgis/admin/machines/localhost/status HTTP/1.1
2019-11-07T18:07:00,414  Got response from HTTP request: <html lang="en">
2019-11-07T18:07:03,673  Executing request POST /arcgis/admin/system/configstore HTTP/1.1
2019-11-07T18:07:03,688  Got response from HTTP request: <html lang="en">

 

There is quite a bit of JSON data embedded in the results above which can be helpful in identifying exactly what a feature service returns to a client when the client queries the service. The timestamps also help if you need to return to the full karaf.log and look for messages logged just before or just after a line matching the command's search patterns to see if there is additional information not captured by the command which might help debug an issue.

Information provided by the timestamps on each logged message can also provide empirical evidence of exactly how long it takes to get a response back from the feature service each time an HTTP request is made. Computing a delta between the date/time a request is logged and the response to the request can be valuable if you suspect latency introduced by geofence synchronization is causing a problem. Remember, nothing happens in zero time, and frequent queries every few seconds to a large feature record set can impact overall GeoEvent Server operations.

Also, keep in mind that a feature service may be configured to return a maximum number of feature records for any given query. GeoEvent Server may have to make several queries to page through a complete feature record set when there are more than 1000 feature records, for example, being imported to update geofences.

The techniques I have described provide a way to delve deeply into geofence synchronization to examine the REST requests and responses when interfacing with a feature service. You can use these techniques to obtain information on request latency as well as implementation details such as how GeoEvent Server pages through large feature record sets or how a feature service handles a number of queries sent in a series. I have attached a PDF illustration of the above two dozen formatted log messages with additional formatting I applied manually to make the JSON in each logged message easy to read. I hope that you find the combination of debug logging with scripted text extraction and string formatting a helpful debugging technique.

– RJ