First published: 09/Jan/2017
Last update: 09/Jan/2017

In chapter Cisco ASA REST API – Part I: Getting started primary configuration for REST API has been done on firewalls then in chapter Cisco ASA REST API – Part III: Checking if prefix is directly connected first script in Perl has been created. Let’s now look at ways we can troubleshoot REST API calls and status on Cisco ASA. This may be crucial to detect cause of the problem. Troubleshooting requires command line access to firewall in enabled mode.

In this chapter I will use script I presented previously and also will execute some REST API methods using Firefox RESTClient extension mentioned if first chapter. Because output of debug can be extensive listings will contain only crucial parts.

Debugging REST API means checking particular component for errors or other logs that might be interested for us. Command execution require in first place declaration which component will be debugged.

asav-1# debug rest-api ?

agent Rest-API Agent
cli Rest-API cli handling
client Rest-API client request handling
daemon Rest-API debug/syslog handling
process Starting/Stopping of Rest-API Agent
token-auth Rest-API Token authentication

 Debugging REST API POST Method

REST API Agent is one of the most crucial components. Let’s look again at the diagram grom Cisco ASA REST API – Part II: How it’s really working?

As you can see REST Agent process in all message exchange between all components so it’s aware of everything that is happening. So from output we can easily check if parameters are parsed correctly and what responses it receive from other modules. Lets look on output when script from chapter XXXX is executed.

[ra agent event]: 2016-12-25 22:21:47,599 DEBUG [startup] The request URI, canonicalized URI, URLDecoded URI respectively are:http://172.16.1.51/api/cli, http://172.16.1.51/api/cli, http://172.16.1.51/api/cli

[ra agent event]: 2016-12-25 22:21:47,600 DEBUG [base] Enter b POST

[ra agent event]: 2016-12-25 22:21:47,600 DEBUG [base] The X-asa-privilege header value got from aware server is:cisco/15

[ra agent event]: 2016-12-25 22:21:47,642 DEBUG [base] parseObjectFromRawPayload() input is:{
          "commands": [
                "show route 10.0.12.5"
          ]
        }

[ra agent event]: 2016-12-25 22:21:47,643 DEBUG [startup] 

!!!!!!!!!!!!!!!!!!!Sending following passed in commands to the device:
      show route 10.0.12.5

[ra agent event]: 2016-12-25 22:21:47,643 DEBUG [k] Command (http://127.0.0.1:8112/admin/config) started

[ra agent event]: 2016-12-25 22:21:47,643 DEBUG [k] POST URL = http://127.0.0.1:8112/admin/config XML:
<?xml version="1.0" encoding="ISO-8859-1"?>
<config-data config-action="merge" errors="continue">
<cli id="0">show route 10.0.12.5</cli>
</config-data>

[ra agent event]: 2016-12-25 22:21:47,657 DEBUG [k] Response:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<!DOCTYPE ErrorList SYSTEM "urn:com-cisco-nm-callhome:ErrorList">
<ErrorList>
<config-failure>
<error-info id="0" type="info">
Routing entry for 10.0.12.0 255.255.255.0
  Known via "connected", distance 0, metric 0 (connected, via interface)
  Routing Descriptor Blocks:
  * directly connected, via asav-2
      Route metric is 0, traffic share count is 1

</error-info>
</config-failure>
</ErrorList>

Response time is 14 milliseconds.

[ra agent event]: 2016-12-25 22:21:47,657 DEBUG [startup] ASA Response : com.cisco.pdm.pdmdata.f[ cli = show route 10.0.12.5 errType = 2 errMsg =
Routing entry for 10.0.12.0 255.255.255.0
  Known via "connected", distance 0, metric 0 (connected, via interface)
  Routing Descriptor Blocks:
  * directly connected, via asav-2
      Route metric is 0, traffic share count is 1

 ]

[ra agent event]: 2016-12-25 22:21:47,657 DEBUG [startup] Committing passed in commands to Device. DONE. Time taken (ms) 14

[ra agent event]: 2016-12-25 22:21:47,658 DEBUG [base] Exit b POST with status code 200

It all starts with decoding URI and then method that will be used on URI (lines 1 an 3) following by checking in privilege level is sufficient for specified user (line 5).

In lines 7-11 we see exact structure of JSON object that has been attached to method. In more complex scripts if we are unsure that we send JSON object with correct values this is a way to do this. It’s very useful because JSON object can be created based on multiple variables also fetched by other subroutines etc.

In our example in lines 13-16 we can see what that command line we specified in JSON object is simply executed internally on firewall. Agent process before sending will translate it into XML format as seen in lines 20-24. Response from LINA process ill also be in XML which is presented in lines 26-40 of the output. Because it’s internal communication we don’t have to worry about understanding the

Ok, but what is happening when we execute other method than CLI command via REST API? Yes and no. It all depends on method you will use. Commands will be displayed for methods PUT, POST, PATCH and DELETE. We won’t see this executing GET method.

More complicated PUT method debug

Here is example of execution of PUT method on static route

[ra agent event]: 2016-12-25 23:53:26,807 DEBUG [startup] The request URI, canonicalized URI, URLDecoded URI respectively are:http://172.16.1.51/api/routing/static/53b77696, http://172.16.1.51/api/routing/static/53b77696, http://172.16.1.51/api/routing/static/53b77696

[ra agent event]: 2016-12-25 23:53:26,808 DEBUG [base] Enter c PUT

[ra agent event]: 2016-12-25 23:53:26,884 DEBUG [base] parseObjectFromRawPayload() input is:{"tunneled":false,"kind":"object#IPv4Route","distanceMetric":5,"tracked":true,"objectId":"390259fa","slamonitorSettings":{"targetInterface":{"kind":"objectRef#Interface","name":"gig2","objectId":"GigabitEthernet0_API_SLASH_2"},"thresholdInMilliseconds":5000,"timeoutInMilliseconds":0,"ToS":0,"dataSizeInBytes":28,"frequencyInSeconds":60,"trackedIP":"1.2.3.4","slaId":6,"numPackets":1},"trackSettings":{"trackId":56},"interface":{"kind":"objectRef#Interface","name":"gig3","objectId":"GigabitEthernet0_API_SLASH_3"},"gateway":{"kind":"IPv4Address","value":"1.2.3.4"},"network":{"kind":"IPv4Network","value":"1.2.3.0/24"}}

[ra agent event]: 2016-12-25 23:53:26,951 DEBUG [startup] 

Sending following commands to the device:
      track 56 rtr 6 reachability
      sla monitor 6
        type echo protocol ipIcmpEcho 1.2.3.4 interface lxc-sshd-5
        timeout 0
      sla monitor  schedule 6 start-time now life forever
      no route asav-3 10.100.48.0 255.255.255.0 10.0.13.3 1
      route lxc-sshd-6 1.2.3.0 255.255.255.0 1.2.3.4 5  track 56

[ra agent event]: 2016-12-25 23:53:26,961 DEBUG [k] POST URL = http://127.0.0.1:8112/admin/config XML:
<?xml version="1.0" encoding="ISO-8859-1"?>
<config-data config-action="merge" errors="continue">
<cli id="0">track 56 rtr 6 reachability</cli>
<cli id="1">sla monitor 6</cli>
<cli id="2">type echo protocol ipIcmpEcho 1.2.3.4 interface lxc-sshd-5</cli>
<cli id="3">timeout 0</cli>
<cli id="4">sla monitor  schedule 6 start-time now life forever</cli>
<cli id="5">no route asav-3 10.100.48.0 255.255.255.0 10.0.13.3 1</cli>
<cli id="6">route lxc-sshd-6 1.2.3.0 255.255.255.0 1.2.3.4 5  track 56</cli>
</config-data>

[ra agent event]: 2016-12-25 23:53:27,032 DEBUG [base] Exit c PUT with status code 204

In this example we execute PUT method that modifies static route entry (lines 1-3). Because this method requires parameters passed as JSON structure the JSON object passed as argument is visible in debug output in line 5. It’s not user friendly as this is raw code, bur you can use jsonviewer.stack.hu to convert it to user readable format and even display as nice tree-based structure.

There are 7 commands that will be execute via CLI by REST API Agent and are listed in output in lines 7-16. Those commands as previously are translated to XML format before internally sending to LINA process (lines 18-28).

Last line ends PUT process and includes status code of execution that is passed to REST Client.

If you looked at the output carefully you should notice on interesting thing. We execute PUT method. But if you look at 18 the actual method executed is POST. This is normal behavior because at the end REST API is nod doing dom magic using hidden firmware feature. All operation are based on CLI and proper parsing of returned values. POST is the method used both internally and by REST Client to execute the command.

Errors

All examples above were from methods that were executed properly. So let’s execute something that won’t be correctly processed by firewall. Let’s delete route that does not exist. In REST API routes are identified by unique identifiers which is passed as a last part of URI. To delete static route we execute following method using non-existing identifier.

DELETE http://172.16.1.51/api/routing/static/393359fa

First indicator of the problem is the return value. We received 404 instead of expected 204 (highlighted in line 64) as well as ERROR description (“RESOURCE-NOT-FOUND”) with full traceback log.

[ra agent error]: 2016-12-26 00:54:06,488 ERROR [base] RESOURCE-NOT-FOUND
 Stack trace:
        at com.cisco.pdm.rest.c.i.db.vb(RestletObjectResource.java:836)
        at com.cisco.pdm.rest.c.i.db.b(RestletObjectResource.java:762)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.restlet.resource.ServerResource.doHandle(ServerResource.java:524)
        at org.restlet.resource.ServerResource.delete(ServerResource.java:216)
        at org.restlet.resource.ServerResource.doHandle(ServerResource.java:623)
        at org.restlet.resource.ServerResource.doNegotiatedHandle(ServerResource.java:679)
        at org.restlet.resource.ServerResource.doConditionalHandle(ServerResource.java:357)
        at org.restlet.resource.ServerResource.handle(ServerResource.java:1014)
        at org.restlet.resource.Finder.handle(Finder.java:246)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Router.doHandle(Router.java:431)
        at org.restlet.routing.Router.handle(Router.java:648)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.engine.application.StatusFilter.doHandle(StatusFilter.java:155)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.engine.CompositeHelper.handle(CompositeHelper.java:211)
        at org.restlet.engine.application.ApplicationHelper.handle(ApplicationHelper.java:84)
        at org.restlet.Application.handle(Application.java:384)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Router.doHandle(Router.java:431)
        at org.restlet.routing.Router.handle(Router.java:648)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Router.doHandle(Router.java:431)
        at org.restlet.routing.Router.handle(Router.java:648)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.engine.application.StatusFilter.doHandle(StatusFilter.java:155)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.routing.Filter.doHandle(Filter.java:159)
        at org.restlet.routing.Filter.handle(Filter.java:206)
        at org.restlet.engine.CompositeHelper.handle(CompositeHelper.java:211)
        at org.restlet.Component.handle(Component.java:406)
        at org.restlet.Server.handle(Server.java:516)
        at org.restlet.engine.connector.ServerHelper.handle(ServerHelper.java:72)
        at org.restlet.engine.adapter.HttpServerHelper.handle(HttpServerHelper.java:152)
        at org.restlet.engine.connector.HttpServerHelper$1.handle(HttpServerHelper.java:73)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
        at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
        at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:677)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
        at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:649)
        at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
        at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:433)
        at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:398)
        at java.lang.Thread.run(Thread.java:745)

[ra agent event]: 2016-12-26 00:54:06,497 DEBUG [base] Exit c DELETE with status code 404

Java on firewall, can that be good? 😉