Re: Throubleshooting Provisioning

rasmus.elmholt · ‎01-29-2021

Hi,

Provisioned a switch(FIAB) in my LAB and then changed some configuration(added a DNS server on an IP Pool)

I then reprovision the switch, but it gave me an error.

When I click the details button I don't really get any information about where the error is:

But then I removed the DNS Sever again from the IP Pool, since it is the only change I have made.

And reprovisioned. But I keep getting the same error.

How do I proceed the troubleshooting from here?

Mike.Cifelli · ‎01-29-2021

A few things to check/consider:

-Are you able to access CLI via SSH and the DNAC username? What do you see when attempting to provision & run a term mon?

-Is the device in your inventory that you are trying to provision synced & fully managed?

-Are there any services down under System360?

See here for additional tshooting items relating to device provisioning:

Cisco SD-Access Provisioning Workflow and Troubleshooting Guide - Cisco

HTH!

rasmus.elmholt · ‎01-30-2021

I can access the switch with SSH. And have just provisioned an extra WLAN, that worked fine.

I have made a catchall EEM and term mon, but do not se any attemt from the DNAC to login and run commands on the switch.

The device is fully managed as af far as I can see.

There are no services down in System360

ChuckMcF · ‎02-02-2021

Look in Provision Focus->Inventory and verify that the last sync status says "Managed". If it does then log into the switch, term mon, then go back to DNAC and Resync the NAD (check the box by the device, go to Actions, Inventory, Resync the Device. click "Yes"). If it is not syncing then you will need to troubleshoot the fault. If you see DNAC communicating with the device then try to Reprovision again. If Reprovision fails then you may want to consider removing the device from inventory, erasing the startup config, reloading, then starting over again. It may just be that something went wrong while you were going through the process of adding it and it is going to require a rebuild of the NAD.

Hope this is helpful,

Chuck McFadden

rasmus.elmholt · ‎02-17-2021

Hi Chuck

I have resynced the device without problems. While I am logged in to the switch and it runs the normal commands.

Rebooted the switch as well but with the same outcome when I try to provision.

ChuckMcF · ‎02-17-2021

Rasmus,

If reprovision fails then try removing the device from inventory. Once successfully removed then erase startup-config, delete the vlan.dat file and reboot. At that point you now have a brand new switch that you are connecting to SDA. Follow the procedures to add it to inventory and then to fabric again. I have found it helpful to remain logged into the switch with term mon enabled while going through each step. You may catch something that is, or isn't, happening while DNAC is doing it's thing.

If you are still having issues provisioning the device after doing this I'd recommend opening a ticket with TAC.

HTH,

Chuck McFadden

rasmus.elmholt · ‎02-17-2021

Hi Mike

Just followed the Tshoot guide, and found some debugging commands on the DNAC.

When I debug I just get some errors that does not make any sense to me:

[Wed Feb 17 12:05:28 UTC] maglev@10.10.8.11 (maglev-master-100-64-0-11) ~
$ magctl service logs -r -f spf-device-manager-service

2021-02-17 12:07:32,794 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | The DefaultMessagePropertiesConverter has finished its job. Now proceeding to add additional hea                                                                                          ders |
2021-02-17 12:07:32,794 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Fetched current headers with keys: [__TypeId__] |
2021-02-17 12:07:32,794 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Got header with __TypeId__ |
2021-02-17 12:07:32,794 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Adding header with key eventName and value com.cisco.apicem.orchestration.taskengine.response.Ex                                                                                          ecutorResponseMessage |
2021-02-17 12:07:32,795 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Adding header Content-Type with value JSON |
2021-02-17 12:07:32,795 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Added header with key security_context |
2021-02-17 12:07:32,795 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | Adding new headers to messageProperties |
2021-02-17 12:07:32,795 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.MaglevAppContainerMessagePropertiesConverter | All done. The message is now ready to be sent to a maglev based app container. |
2021-02-17 12:07:32,795 |  DEBUG | tatusUpdaterTaskAdapter-4 |  | c.c.g.a.i.GrapevineMessageListener | Acking delivery tag = 17 |
2021-02-17 12:07:32,850 |  DEBUG | rgeTaskExecutionAdapter-2 |  | c.c.g.a.i.GrapevineMessageListener | Received message=com.cisco.apicem.orchestration.taskengine.request.ExecutorMessage, retries=0, maxRetries=5 |
2021-02-17 12:07:32,850 |  DEBUG | rgeTaskExecutionAdapter-2 |  | c.c.g.a.i.RbacSecurityContextHelper | Deserialized RBACSecurityContext {userId='5fcfee942e250700c7cc62ea'userName='admin'tenantId='5fcfee932e250700c7cc62                                                                                          e7'tenantName='TNT0'roleIdList='["5fcfee942e250700c7cc62e9"]'authSource='internal'globalScopeId='null', groupInstanceIds=[], groupInstanceUuids=[], roleScopeListMap={}} |
2021-02-17 12:07:32,851 |  DEBUG | rgeTaskExecutionAdapter-2 |  | c.c.g.a.i.RbacSecurityContextHelper | Thread Local - RBACSecurityContext {userId='5fcfee942e250700c7cc62ea'userName='admin'tenantId='5fcfee932e250700c7cc                                                                                          62e7'tenantName='TNT0'roleIdList='["5fcfee942e250700c7cc62e9"]'authSource='internal'globalScopeId='null', groupInstanceIds=[], groupInstanceUuids=[], roleScopeListMap={}} |
2021-02-17 12:07:32,851 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.e.AbstractMessageExecutor | Received request for task execution: ExecutorMessage.Request:{ workflowId: 076e1817-f221-4a44-83a8-74a4f1866062; ta                                                                                          skId: db844ece-bb6c-4ffa-882a-60754356ee6e; executorType: spf.rfsMergeTaskExecutionAdapter; executorAction: null; targetId: Default; shardId: 2; executionContextId: 8972db64-1c02-442a-94c5-cc71e763ee74} |
2021-02-17 12:07:32,852 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.e.AbstractMessageExecutor | Calling the execute on workflowTask db844ece-bb6c-4ffa-882a-60754356ee6e  |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.u.DeviceManagerCommonUtil | get rfs workflow info from input |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.u.DeviceManagerCommonUtil | adding namespace version pairs. serializedNamespaceVersionTargetIdsMap = {"@class":"java.util.HashMap","{\"@class                                                                                          \":\"com.cisco.apic.controller.spf.api.context.NamespaceVersionPair\",\"instanceUuid\":\"b6714a7e-8793-484e-8f38-d490f47fca6c\",\"snapshotVersion\":28,\"snapshotNamespace\":\"1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3\"}":["j                                                                                          ava.util.ArrayList",["d632d78b-851c-40c8-867c-95a55393f98e"]]} |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.u.DeviceManagerCommonUtil | returning rfsWorkflowInfo = RfsWorkflowInfo [cfsId=dfd22199-4816-4f1c-8f48-d0a6e7fa55ab, namespace=1ea9588e-f875-                                                                                          4b2c-b9d1-25cdf8ec07b3, type=DeviceInfo, qualifier=null, version=28, operation=modify, targetId=Default, taskId=9a70889f-b531-4462-9c6a-6a7d5db2294f, rootRfsSnapshotKey=null, serializedProvisioningData=null, lockedDevic                                                                                          eIds=[], namespaceVersionPairs=[NamespaceVersionPair [snapshotVersion=28, snapshotNamespace=1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3]], rollbackFromNamespaceVersionPairsMap=null, namespaceVersionUnmanagedTargetsMap={}, name                                                                                          spaceVersionTargetsMap={NamespaceVersionPair [snapshotVersion=28, snapshotNamespace=1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3]=[d632d78b-851c-40c8-867c-95a55393f98e]}, targetIdsToProvision=[d632d78b-851c-40c8-867c-95a55393f9                                                                                          8e], deployRFSResult=null, stopExecution=false, workflowTaskStatus=null, clientType=null, userName=admin, spfTaskAdapterInfo=null, targetDeviceSequence=[], scratchPadInstanceUuid=null, scratchPadComments=null, isRollbac                                                                                          kEnabled=false, isRollbackFlow=false, rollbackFromVersion=0, isRestoreToOriginal=false, skipTranslateRfsForRestore=false, rfsMgmtCapInfo=null, lockParams=null, corelationData=null] |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | ----------------------------------------- |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | Inside spf.rfsMergeTaskExecutionAdapter Task |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | ----------------------------------------- |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | [taskName : Determination of network intent deployment status, taskId : db844ece-bb6c-4ffa-882a-60754356ee6e, workf                                                                                          lowId: 076e1817-f221-4a44-83a8-74a4f1866062], [provisionTaskId: 9a70889f-b531-4462-9c6a-6a7d5db2294f], Started executing spf.rfsMergeTaskExecutionAdapter |
2021-02-17 12:07:32,854 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | [rollbackInfo : isRollbackEnabled: false, isRollbackFlow: false] |
2021-02-17 12:07:32,868 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.u.DeviceManagerCommonUtil | 1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3_28_Default - UPDATE_CFS_PROVISIONING_STATUS running |
2021-02-17 12:07:32,871 |  ERROR | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | [taskName : Determination of network intent deployment status, taskId : db844ece-bb6c-4ffa-882a-60754356ee6e, workf                                                                                          lowId: 076e1817-f221-4a44-83a8-74a4f1866062], NCSP10025: Provisioning failed. |
2021-02-17 12:07:32,872 |  ERROR | rgeTaskExecutionAdapter-2 |  | c.cisco.dnac.error.log.ErrorLogger | NCSP10025: Provisioning failed.
com.cisco.apic.controller.spf.api.exception.ServiceProvisioningException: NCSP10025: Provisioning failed.
        at com.cisco.apicem.device.manager.service.taskadapter.RfsMergeTaskExecutionAdapter.updateCfsProvisioningStatus(RfsMergeTaskExecutionAdapter.java:694)
        at com.cisco.apicem.device.manager.service.taskadapter.RfsMergeTaskExecutionAdapter.doExecute(RfsMergeTaskExecutionAdapter.java:158)
        at com.cisco.apic.controller.spf.taskadapter.SPFTaskExecutionAdapter.execute(SPFTaskExecutionAdapter.java:298)
        at com.cisco.apicem.orchestration.taskengine.executor.ExecutorMessageExecutor.execute(ExecutorMessageExecutor.java:103)
        at com.cisco.apicem.orchestration.taskengine.request.handler.ExecutorMessageHandler.handleRequest(ExecutorMessageHandler.java:38)
        at com.cisco.grapevine.amqp.impl.GrapevineMessageListener.invokeHandler_aroundBody0(GrapevineMessageListener.java:376)
        at com.cisco.grapevine.amqp.impl.GrapevineMessageListener$AjcClosure1.run(GrapevineMessageListener.java:1)
        at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:149)
        at com.cisco.enc.i18n.localization.aop.EnableI18nOnRequestHandler.getEmptyResponse(EnableI18nOnRequestHandler.java:26)
        at com.cisco.grapevine.amqp.impl.GrapevineMessageListener.invokeHandler(GrapevineMessageListener.java:349)
        at com.cisco.grapevine.amqp.impl.GrapevineMessageListener.onMessage(GrapevineMessageListener.java:195)
        at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:546)
        at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:472)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$001(SimpleMessageListenerContainer.java:61)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$1.invokeListener(SimpleMessageListenerContainer.java:110)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.invokeListener(SimpleMessageListenerContainer.java:611)
        at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:454)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:474)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:458)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$300(SimpleMessageListenerContainer.java:61)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:551)
        at java.base/java.lang.Thread.run(Thread.java:834)
 |
2021-02-17 12:07:32,873 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.c.s.t.SPFTaskExecutionAdapter | Marking workflow task as failure |
2021-02-17 12:07:32,873 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.t.RfsMergeTaskExecutionAdapter | updating service deployment status for cfs namespace = 1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3 version = 28 isE                                                                                          rror = true |
2021-02-17 12:07:32,877 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.u.DeviceManagerCommonUtil | 1ea9588e-f875-4b2c-b9d1-25cdf8ec07b3_28_Default - UPDATE_CFS_PROVISIONING_STATUS success |
2021-02-17 12:07:32,877 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.d.m.s.t.RfsMergeTaskExecutionAdapter | Added targetIds [d632d78b-851c-40c8-867c-95a55393f98e] for sprGroup with namespace 1ea9588e-f875-4b2c-b9d1-2                                                                                          5cdf8ec07b3, version 28 |
2021-02-17 12:07:32,894 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.task.WorkflowTaskContext | Keysspf.spr.groups to be fetched from DB |
2021-02-17 12:07:32,897 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.task.WorkflowTaskContext | No.of Context Params picked from DB:2 |
2021-02-17 12:07:32,897 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.task.WorkflowTaskContext | Keysspf.cfs.type to be fetched from DB |
2021-02-17 12:07:32,899 |   INFO | rgeTaskExecutionAdapter-2 |  | c.c.a.o.t.task.WorkflowTaskContext | No.of Context Params picked from DB:5 |

rasmus.elmholt · ‎02-17-2021

Hi Mike

I have been through the steps in the tshoot guide and have found this is the log, but have no idear what to do about it.

[Wed Feb 17 12:40:53 UTC] maglev@10.10.8.11 (maglev-master-100-64-0-11) ~
$ magctl service logs -r spf-service-manager | grep "Creating task"
2021-02-17 07:54:53,342 |   INFO | qtp1287934450-87792       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 29c842eb-7603-4c8e-b0a0-af06209f9f9e |
2021-02-17 07:56:30,941 |   INFO | qtp1287934450-87792       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 92dd5d38-9239-4bdf-9daf-63034b42df5f |
2021-02-17 08:05:46,497 |   INFO | qtp1287934450-87825       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 33c40060-e065-49c3-86bb-31563837a933 |
2021-02-17 08:10:25,340 |   INFO | qtp1287934450-87822       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 78836d62-90f3-47f4-9880-9dacd86c83ef |
2021-02-17 08:30:46,438 |   INFO | qtp1287934450-87823       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 39e73f38-caae-4fb7-b219-e29d95c21924 |
2021-02-17 08:31:54,392 |   INFO | qtp1287934450-87860       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: a80bde4b-0570-49b7-8298-b6b01e9029bc |
2021-02-17 08:34:56,350 |   INFO | qtp1287934450-87858       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: c522cccd-bcf5-443d-9d6a-14596c6e4fdc |
2021-02-17 12:07:20,012 |   INFO | qtp1287934450-88103       |  | c.c.a.c.s.e.ServiceProvisionEngineController | ==> Creating task: 9a70889f-b531-4462-9c6a-6a7d5db2294f |

[Wed Feb 17 12:40:59 UTC] maglev@10.10.8.11 (maglev-master-100-64-0-11) ~
$ magctl service logs -r spf-service-manager | grep -A 1000 "Creating task: 9a70889f-b531-4462-9c6a-6a7d5db2294f" | grep ERROR
2021-02-17 12:07:24,428 |  ERROR | Translate_Cfs_Thread_3    |  | c.cisco.dnac.error.log.ErrorLogger | NCSO10002: Conflicting configuration present on device. dhcp server snooping already present |
2021-02-17 12:07:24,428 |  ERROR | Translate_Cfs_Thread_3    |  | c.cisco.dnac.error.log.ErrorLogger | NCSO10002: Conflicting configuration present on device. dhcp server snooping already present |
2021-02-17 12:07:24,735 |  ERROR | Translate_Cfs_Thread_3    |  | c.c.e.l.rfs.helper.LanRfsGenerator | auth key cannot be empty |
2021-02-17 12:07:24,748 |  ERROR | Translate_Cfs_Thread_3    |  | c.c.e.l.rfs.helper.LanRfsGenerator | auth key cannot be empty |
2021-02-17 12:07:24,757 |  ERROR | Translate_Cfs_Thread_3    |  | c.c.e.l.rfs.helper.LanRfsGenerator | auth key cannot be empty |
2021-02-17 12:07:25,476 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - ruleIndexgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,476 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - ruleActiongiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,476 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - sourceAddressgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,476 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - sourceMaskgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,476 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - startSourcePortgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,477 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - endSourcePortgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,477 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - destinationAddressgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,477 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - destinationMaskgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,477 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - startDestinationPortgiven for feature = PreAuthGuestACLConfig doesn't exists |
2021-02-17 12:07:25,477 |  ERROR | fsTranslatorTaskAdapter-2 |  | com.cisco.enc.dna.spf.util.SPFUtil | Model Field - endDestinationPortgiven for feature = PreAuthGuestACLConfig doesn't exists |

Everything seems okay from the GUI on the DNAC. Configuration wise.

Mike.Cifelli · ‎02-17-2021

The logs seem to be complaining about some conflicting configuration on the device already. Are you able to check the box 'Provision these templates even if they have been deployed before' during provisioning to see if that gives you a different result? You could also attempt to manually remove the config from CLI that the logs are complaining about that are already present, then re-prov, and check the logs again. I have done that in the past with similar errors, but that can be tedious. I would suggest engaging with TAC, or as @ChuckMcF mentioned your best bet may be to completely remove device from inventory & remove the config, which will essentially allow you to start from scratch.