PNP no longer working

[zlantz]

We have been using PNP for a while now. We have had some issues, but we have been slowly figuring them out one by one and giving feedback when possible. However, recently I have been running into an issue where my deployments can get to the controller and the controller updates the rule status to "Getting Device Info" and never continues after that point. 16 minutes go by and the deployment fails. I have mentioned this issue before in a long extended thread and wanted to move it over to a new thread. Old thread for reference: {PNP}Streamlining Zero-Touch

We are using option 43 for deployment:

"5A1D;B2;K5;I10.255.72.116;J443"

We were recently experimenting with pnp startup vlan and having issues as our 6Ks are still running 15.1, for now. I am also having this issue in my lab with a 6K that is running 15.4.

Output of sh pnp trace:

Switch#sh pnp trace

[03/13/17 17:14:47.254 UTC 1 398] Info: Startup config does not exists

[03/13/17 17:14:47.254 UTC 2 398] start_pnpa_discovery: PnP Discovery trial number[1]

[03/13/17 17:14:47.254 UTC 3 398] start_pnpa_discovery: Initiating PnP discovery manager

[03/13/17 17:14:47.254 UTC 4 398] pnpa_discovery_autoinstall_pid_create: waiting for autoinstall

[03/13/17 17:15:22.882 UTC 5 398] pnpa_discovery_autoinstall_pid_create:Received autoinstall complete status

[03/13/17 17:15:27.884 UTC 6 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 17:15:27.884 UTC 7 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 17:15:32.886 UTC 8 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/13/17 17:15:32.886 UTC 9 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/13/17 17:15:32.887 UTC A 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/13/17 17:15:32.887 UTC B 398] pnpa_disc_dhcp_option_43: op43 transport 2

[03/13/17 17:15:32.887 UTC C 398] pnpa_disc_dhcp_option_43: transport https

[03/13/17 17:15:32.887 UTC D 398] pnpa_validate_port_type: Port is 443

[03/13/17 17:15:32.887 UTC E 398] pnpa_disc_dhcp_option_43: op43 port 443

[03/13/17 17:15:32.887 UTC F 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/13/17 17:15:32.887 UTC 10 398] pnpa_dhcp_discovery:URL[http://10.255.72.116/ca/trustpool]

[03/13/17 17:15:32.907 UTC 11 398] pnp_validate_ca_bundle_url:CA bundle [http://10.255.72.116/ca/trustpool] present

[03/13/17 17:15:32.908 UTC 12 398] pnp_setup_abort:Setup abort initiated

[03/13/17 17:15:32.908 UTC 13 398] HA registry indicates presence of standby

[03/13/17 17:15:32.908 UTC 14 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/13/17 17:15:32.908 UTC 15 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/13/17 17:15:32.908 UTC 16 398] pnpa_ntp_sync : Unable to configure NTP Server IP[10.255.72.116]

[03/13/17 17:15:32.909 UTC 17 398] pnpa_disc_trustpool_install: NTP sync unsuccessful

[03/13/17 17:15:32.909 UTC 18 398] pnpa_trustpool_bundle_install: Config and ha safe check [NOT OK] for trustpool installation[try:0]

[03/13/17 17:15:32.909 UTC 19 398] pnpa_trustpool_bundle_install: Config and ha safe check [NOT OK] for trustpool installation[try:1]

[03/13/17 17:15:32.909 UTC 1A 398] pnpa_disc_trustpool_install: Trustpool installation unsuccessful

[03/13/17 17:15:32.916 UTC 1B 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/13/17 17:15:32.916 UTC 1C 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/13/17 17:15:32.916 UTC 1D 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/13/17 17:15:32.916 UTC 1E 398] pnpa_disc_dhcp_option_43: op43 transport 2

[03/13/17 17:15:32.916 UTC 1F 398] pnpa_disc_dhcp_option_43: transport https

[03/13/17 17:15:32.916 UTC 20 398] pnpa_validate_port_type: Port is 443

[03/13/17 17:15:32.916 UTC 21 398] pnpa_disc_dhcp_option_43: op43 port 443

[03/13/17 17:15:32.916 UTC 22 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/13/17 17:15:32.916 UTC 23 398] pnpa_dhcp_discovery:URL[http://10.255.72.116/ca/trustpool]

[03/13/17 17:15:32.935 UTC 24 398] pnp_validate_ca_bundle_url:CA bundle [http://10.255.72.116/ca/trustpool] present

[03/13/17 17:15:32.935 UTC 25 398] pnp_setup_abort:Setup abort initiated

[03/13/17 17:15:32.935 UTC 26 398] HA registry indicates presence of standby

[03/13/17 17:15:32.935 UTC 27 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/13/17 17:15:32.935 UTC 28 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/13/17 17:15:32.935 UTC 29 398] pnpa_ntp_sync : Unable to configure NTP Server IP[10.255.72.116]

[03/13/17 17:15:32.935 UTC 2A 398] pnpa_disc_trustpool_install: NTP sync unsuccessful

[03/13/17 17:15:32.936 UTC 2B 398] 10.stdby Disabled;

[03/13/17 17:15:36.730 UTC 2C 398] pnpa_trustpool_bundle_install: Config and ha safe check [OK] for trustpool installation[try:0]

[03/13/17 17:15:36.730 UTC 2D 398] pnpa_disc_trustpool_install: Trustpool installation Successful

[03/13/17 17:15:36.730 UTC 2E 398] pnp_httpc_register: PnP httpc registered

[03/13/17 17:15:36.730 UTC 2F 398] get_pnp_work_req_url: Port is 443

[03/13/17 17:15:36.730 UTC 30 398] send_work_req: HTTPS URL = https://10.255.72.116:443/pnp/HELLO

[03/13/17 17:15:36.730 UTC 31 398] send_work_req: INITIATING HTTPS SEND GET REQUEST...

[03/13/17 17:15:36.731 UTC 32 398] pnp_httpc_send_get: url https://10.255.72.116:443/pnp/HELLO

[03/13/17 17:15:36.731 UTC 33 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/13/17 17:15:36.737 UTC 34 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/13/17 17:15:36.737 UTC 35 311] pnp_resp_data: request status Response data recieved, successfully

[03/13/17 17:15:36.737 UTC 36 311] pnp_resp_data: DATA STARTS HERE

[03/13/17 17:15:36.737 UTC 37 311] pnp_resp_data: DATA ENDS HERE

[03/13/17 17:15:36.737 UTC 38 311] pnp_resp_data: Status of this transaction is 200

[03/13/17 17:15:36.737 UTC 39 311] pnp_resp_data: Length of data handed over 21

[03/13/17 17:15:36.737 UTC 3A 311] pnp_resp_data: session id       : 6

[03/13/17 17:15:36.737 UTC 3B 311] pnp_resp_data: transaction id   : 4

[03/13/17 17:15:36.737 UTC 3C 311] pnp_resp_data: status_code      : 200

[03/13/17 17:15:36.738 UTC 3D 311] pnp_resp_data: status_string    : OK

[03/13/17 17:15:36.738 UTC 3E 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/13/17 17:15:36.738 UTC 3F 311] pnp_resp_data: content_encoding :

[03/13/17 17:15:36.738 UTC 40 311] pnp_resp_data: content_length   : 21

[03/13/17 17:15:36.738 UTC 41 311] pnp_resp_data: Location         :

[03/13/17 17:15:36.738 UTC 42 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/13/17 17:15:36.738 UTC 43 311] pnp_resp_data: Data has not been cached

[03/13/17 17:15:36.738 UTC 44 311] pnp_http_resp_data_free: pnp response data freed

[03/13/17 17:15:36.739 UTC 45 398] pnp_httpc_send_get: HTTPS send success()

[03/13/17 17:15:36.739 UTC 46 398] send_work_req: Free url_https 1

[03/13/17 17:15:36.739 UTC 47 398] send_work_req: HTTPS SEND GET REQUEST SUCCESS

[03/13/17 17:15:36.739 UTC 48 398] 11.stdby Disabled;

[03/13/17 17:15:36.739 UTC 49 398] HA registry indicates NO standby up

[03/13/17 17:15:36.739 UTC 4A 398] 12.stdby Disabled;

[03/13/17 17:15:37.814 UTC 4B 398] HA, config safe check [OK], for configuring[try:0]

[03/13/17 17:15:37.814 UTC 4C 398] pnpa_dhcp_discovery:Configured pnp profile

[03/13/17 17:15:37.814 UTC 4D 398] pnp_setup_abort:Setup abort initiated

[03/13/17 17:15:37.814 UTC 4E 398] start_pnpa_discovery: PnP discovery process successful

[03/13/17 17:15:37.814 UTC 4F 398] pnp_autoinstall_terminate: Terminating ip autoinstall

[03/13/17 17:15:37.814 UTC 50 398] pnp_autoinstall_terminate: Terminating DHCP autoinstall

[03/13/17 17:16:20.941 UTC 51 284] 13.stdby Disabled;

[03/13/17 17:16:20.941 UTC 52 284] 14.stdby Disabled;

[03/13/17 17:16:20.941 UTC 53 284] HA registry indicates NO standby up

[03/13/17 17:16:20.941 UTC 54 284] 15.stdby Disabled;

[03/13/17 17:29:37.129 UTC 55 284] HA, config safe check [OK], for configuring[try:0]

[ngoldwat]

Hi,

What happens if you change the option 43 to: 5A1N;B2;K4;I10.255.72.116;J80 ?

1st contact is HTTP then it switches to HTTPS.

Thanks

[zlantz]

This also does not work. I also see the same symptoms in the GUI. The only thing that I can think of that has changed with the controller recently is that we were finally able to add a cert to access the controller GUI after a lengthy TAC case to resolve some issues we were seeing when trying to add the cert.  Here is the trace when trying to use port 80:

Switch#sh pnp trace

[03/13/17 19:44:41.900 UTC 1 398] Info: Startup config does not exists

[03/13/17 19:44:41.900 UTC 2 398] start_pnpa_discovery: PnP Discovery trial number[1]

[03/13/17 19:44:41.900 UTC 3 398] start_pnpa_discovery: Initiating PnP discovery manager

[03/13/17 19:44:41.900 UTC 4 398] pnpa_discovery_autoinstall_pid_create: waiting for autoinstall

[03/13/17 19:45:17.536 UTC 5 398] pnpa_discovery_autoinstall_pid_create:Received autoinstall complete status

[03/13/17 19:45:22.531 UTC 6 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 19:45:22.531 UTC 7 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 19:45:27.533 UTC 8 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/13/17 19:45:27.533 UTC 9 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/13/17 19:45:27.533 UTC A 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/13/17 19:45:27.533 UTC B 398] pnpa_disc_dhcp_option_43: op43 transport 1

[03/13/17 19:45:27.533 UTC C 398] pnpa_disc_dhcp_option_43: transport http

[03/13/17 19:45:27.534 UTC D 398] pnpa_validate_port_type: Port is 80

[03/13/17 19:45:27.534 UTC E 398] pnpa_disc_dhcp_option_43: op43 port 80

[03/13/17 19:45:27.534 UTC F 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/13/17 19:45:27.534 UTC 10 398] pnp_httpc_register: PnP httpc registered

[03/13/17 19:45:27.534 UTC 11 398] get_pnp_work_req_url: Port is 80

[03/13/17 19:45:27.534 UTC 12 398] pnp_httpc_send_get: url http://10.255.72.116:80/pnp/HELLO

[03/13/17 19:45:27.534 UTC 13 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/13/17 19:45:27.549 UTC 14 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/13/17 19:45:27.549 UTC 15 311] pnp_resp_data: request status Response data recieved, successfully

[03/13/17 19:45:27.549 UTC 16 311] pnp_resp_data: DATA STARTS HERE

[03/13/17 19:45:27.549 UTC 17 311] pnp_resp_data: DATA ENDS HERE

[03/13/17 19:45:27.549 UTC 18 311] pnp_resp_data: Status of this transaction is 200

[03/13/17 19:45:27.549 UTC 19 311] pnp_resp_data: Length of data handed over 21

[03/13/17 19:45:27.550 UTC 1A 311] pnp_resp_data: session id       : 3

[03/13/17 19:45:27.550 UTC 1B 311] pnp_resp_data: transaction id   : 1

[03/13/17 19:45:27.550 UTC 1C 311] pnp_resp_data: status_code      : 200

[03/13/17 19:45:27.550 UTC 1D 311] pnp_resp_data: status_string    : OK

[03/13/17 19:45:27.550 UTC 1E 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/13/17 19:45:27.550 UTC 1F 311] pnp_resp_data: content_encoding :

[03/13/17 19:45:27.550 UTC 20 311] pnp_resp_data: content_length   : 21

[03/13/17 19:45:27.550 UTC 21 311] pnp_resp_data: Location         :

[03/13/17 19:45:27.550 UTC 22 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/13/17 19:45:27.551 UTC 23 311] pnp_resp_data: Data has not been cached

[03/13/17 19:45:27.551 UTC 24 311] pnp_http_resp_data_free: pnp response data freed

[03/13/17 19:45:27.551 UTC 25 398] pnp_httpc_send_get: HTTP send success()

[03/13/17 19:45:27.551 UTC 26 398] send_work_req: HTTP SEND GET REQUEST SUCCESS

[03/13/17 19:45:27.551 UTC 27 398] HA registry indicates presence of standby

[03/13/17 19:45:27.551 UTC 28 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/13/17 19:45:27.551 UTC 29 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/13/17 19:45:27.552 UTC 2A 398] pnpa_dhcp_discovery:PnP profile config unsuccessful

[03/13/17 19:45:27.558 UTC 2B 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/13/17 19:45:27.558 UTC 2C 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/13/17 19:45:27.558 UTC 2D 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/13/17 19:45:27.558 UTC 2E 398] pnpa_disc_dhcp_option_43: op43 transport 1

[03/13/17 19:45:27.558 UTC 2F 398] pnpa_disc_dhcp_option_43: transport http

[03/13/17 19:45:27.558 UTC 30 398] pnpa_validate_port_type: Port is 80

[03/13/17 19:45:27.558 UTC 31 398] pnpa_disc_dhcp_option_43: op43 port 80

[03/13/17 19:45:27.558 UTC 32 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/13/17 19:45:27.558 UTC 33 398] pnp_httpc_register: PnP Already registered with httpc

[03/13/17 19:45:27.558 UTC 34 398] get_pnp_work_req_url: Port is 80

[03/13/17 19:45:27.558 UTC 35 398] pnp_httpc_send_get: url http://10.255.72.116:80/pnp/HELLO

[03/13/17 19:45:27.559 UTC 36 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/13/17 19:45:27.563 UTC 37 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/13/17 19:45:27.563 UTC 38 311] pnp_resp_data: request status Response data recieved, successfully

[03/13/17 19:45:27.563 UTC 39 311] pnp_resp_data: DATA STARTS HERE

[03/13/17 19:45:27.563 UTC 3A 311] pnp_resp_data: DATA ENDS HERE

[03/13/17 19:45:27.563 UTC 3B 311] pnp_resp_data: Status of this transaction is 200

[03/13/17 19:45:27.563 UTC 3C 311] pnp_resp_data: Length of data handed over 21

[03/13/17 19:45:27.563 UTC 3D 311] pnp_resp_data: session id       : 3

[03/13/17 19:45:27.563 UTC 3E 311] pnp_resp_data: transaction id   : 2

[03/13/17 19:45:27.563 UTC 3F 311] pnp_resp_data: status_code      : 200

[03/13/17 19:45:27.563 UTC 40 311] pnp_resp_data: status_string    : OK

[03/13/17 19:45:27.563 UTC 41 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/13/17 19:45:27.563 UTC 42 311] pnp_resp_data: content_encoding :

[03/13/17 19:45:27.563 UTC 43 311] pnp_resp_data: content_length   : 21

[03/13/17 19:45:27.563 UTC 44 311] pnp_resp_data: Location         :

[03/13/17 19:45:27.563 UTC 45 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/13/17 19:45:27.563 UTC 46 311] pnp_resp_data: Data has not been cached

[03/13/17 19:45:27.563 UTC 47 311] pnp_http_resp_data_free: pnp response data freed

[03/13/17 19:45:27.563 UTC 48 398] pnp_httpc_send_get: HTTP send success()

[03/13/17 19:45:27.564 UTC 49 398] send_work_req: HTTP SEND GET REQUEST SUCCESS

[03/13/17 19:45:27.564 UTC 4A 398] HA registry indicates presence of standby

[03/13/17 19:45:27.564 UTC 4B 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/13/17 19:45:27.564 UTC 4C 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/13/17 19:45:27.564 UTC 4D 398] pnpa_dhcp_discovery:PnP profile config unsuccessful

[03/13/17 19:45:32.572 UTC 4E 398] pnpa_dns_discovery: Starting PnP DNS discovery

[03/13/17 19:45:32.572 UTC 4F 398] pnpa_disc_dhcp_dns: domain name ***REDACTED*** on interface Vlan1

[03/13/17 19:45:41.569 UTC 50 398] pnpa_disc_dhcp_dns:Host name address resolution failed

[03/13/17 19:45:41.569 UTC 51 398] pnpa_dns_discovery:DNS discovery not successful

[03/13/17 19:45:41.569 UTC 52 398] pnpa_dns_discovery: Starting PnP DNS discovery

[03/13/17 19:45:41.569 UTC 53 398] pnpa_disc_dhcp_dns: domain name ***REDACTED*** on interface Vlan1

[03/13/17 19:45:41.569 UTC 54 398] pnpa_disc_dhcp_dns:Host name address resolution failed

[03/13/17 19:45:41.569 UTC 55 398] pnpa_dns_discovery:DNS discovery not successful

[03/13/17 19:45:46.572 UTC 56 398] pnpa_cco_discovery: starting CCO discovery

[03/13/17 19:45:55.581 UTC 57 398] pnpa_cco_discovery: Hostname resolution failed

[03/13/17 19:45:55.581 UTC 58 398] pnpa_cco_discovery: starting CCO discovery

[03/13/17 19:45:55.581 UTC 59 398] pnpa_cco_discovery: Hostname resolution failed

[03/13/17 19:46:00.580 UTC 5A 398] pnpa_discovery_manager: Starting NAPP

[03/13/17 19:46:00.580 UTC 5B 398] pnpa_napp_discovery: starting NAPP discovery

[03/13/17 19:46:00.580 UTC 5C 398] set_intf_state_for_napp: Setting interface state for NAPP

[03/13/17 19:46:00.580 UTC 5D 398] pnp_pxc_recv_init: enter

[03/13/17 19:46:00.581 UTC 5E 398] pnp_pxc_send_init: pnp_pxc_xmt_process created. listener_pid=284

[03/13/17 19:46:00.581 UTC 5F 176] pnp_pxc_rcv_process: Begin

[03/13/17 19:46:00.581 UTC 60 176] pnp_pxd_new_workspace: New packet workspace 0x3BDA76E0

[03/13/17 19:46:00.581 UTC 61 176] pnp_pxc_create_recv_socket: enter

[03/13/17 19:46:00.586 UTC 62 176] pnp_pxc_create_recv_socket: done

[03/13/17 19:46:00.586 UTC 63 176] pnp_pxc_rcv_loop: enter

[03/13/17 19:46:00.587 UTC 64 284] pnp_pxc_xmt_process: Entering sending loop.

[03/13/17 19:46:00.650 UTC 65 284] pnp_pxc_xmt_loop: str_port_len = 4

[03/13/17 19:46:00.650 UTC 66 284] pnp_pxc_xmt_loop: client_port_no  = 1029

[03/13/17 19:46:00.650 UTC 67 284] pnp_pxc_xmt_loop: str_client_ip_len = 7

[03/13/17 19:46:00.651 UTC 68 284] pnp_pxc_xmt_loop: pxy_client_ip = 0.0.0.0

[03/13/17 19:46:00.651 UTC 69 284] pnp_pxc_xmt_loop: String hello = OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP1213:WS-C3650-24PSOP133:1.0OP144:1029OP157:0.0.0.0

[03/13/17 19:46:00.656 UTC 6A 284] pnp_pxc_xmt_loop: sendto returns 99

[03/13/17 19:46:00.656 UTC 6B 284] pnp_pxc_xmt_loop: PROXY CLIENT: sent data = OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP1213:WS-C3650-24PSOP133:1.0OP144:1029OP157:0.0.0.0

[03/13/17 19:47:00.648 UTC 6C 284] pnp_pxc_rcv_cleanup: setting FAIL discovery

[03/13/17 19:47:00.648 UTC 6D 284] pnp_pxc_xmt_loop - Killing proxy client sending and receiving processes

[03/13/17 19:47:00.649 UTC 6E 284] send_timeout_response: Timeout status response sent for client 'PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084' : OPRESPSTATUS:OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP123:1.0OP13OPTRANSS19:TRANSACTION TIMEOUTOPSTATUS33:PROXY CLIENT RETRY COUNT EXCEEDEDOPERRMSG75:Proxy client retry count exceeded. Proxy client process is no longer active

[03/13/17 19:47:00.649 UTC 6F 284] create_pnp_pxc_timeout_response_socket: Socket open succeeded

[03/13/17 19:47:00.654 UTC 70 284] destroy_pnp_pxc_timeout_response_socket: Closing socket

[03/13/17 19:47:00.654 UTC 71 284] pnp_pxc_xmt_process: Sending loop exited.

[03/13/17 19:47:00.654 UTC 72 284] pnp_pxc_xmt_cleanup: enter

[03/13/17 19:47:00.654 UTC 73 284] pnp_pxc_xmt_cleanup: Closing socket

[03/13/17 19:47:00.655 UTC 74 284] pnp_pxc_xmt_cleanup: Killing process

[03/13/17 19:47:00.655 UTC 75 398] pnp_wait_on_napp:Received NAPP complete status

[03/13/17 19:47:05.649 UTC 76 398] Info: PnP profile configuration was unsuccessful

[03/13/17 19:47:05.649 UTC 77 398] start_pnpa_discovery: PnP discovery process failed

[03/13/17 19:47:15.647 UTC 78 398] Info: Startup config does not exists

[03/13/17 19:47:15.647 UTC 79 398] start_pnpa_discovery: PnP Discovery trial number[2]

[03/13/17 19:47:15.647 UTC 7A 398] start_pnpa_discovery: Initiating PnP discovery manager

[03/13/17 19:47:20.653 UTC 7B 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 19:47:20.653 UTC 7C 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/13/17 19:47:25.651 UTC 7D 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/13/17 19:47:25.651 UTC 7E 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/13/17 19:47:25.651 UTC 7F 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/13/17 19:47:25.651 UTC 80 398] pnpa_disc_dhcp_option_43: op43 transport 1

[03/13/17 19:47:25.651 UTC 81 398] pnpa_disc_dhcp_option_43: transport http

[03/13/17 19:47:25.651 UTC 82 398] pnpa_validate_port_type: Port is 80

[03/13/17 19:47:25.651 UTC 83 398] pnpa_disc_dhcp_option_43: op43 port 80

[03/13/17 19:47:25.651 UTC 84 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/13/17 19:47:25.651 UTC 85 398] pnp_httpc_register: PnP Already registered with httpc

[03/13/17 19:47:25.651 UTC 86 398] get_pnp_work_req_url: Port is 80

[03/13/17 19:47:25.651 UTC 87 398] pnp_httpc_send_get: url http://10.255.72.116:80/pnp/HELLO

[03/13/17 19:47:25.652 UTC 88 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/13/17 19:47:25.657 UTC 89 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/13/17 19:47:25.657 UTC 8A 311] pnp_resp_data: request status Response data recieved, successfully

[03/13/17 19:47:25.657 UTC 8B 311] pnp_resp_data: DATA STARTS HERE

[03/13/17 19:47:25.657 UTC 8C 311] pnp_resp_data: DATA ENDS HERE

[03/13/17 19:47:25.657 UTC 8D 311] pnp_resp_data: Status of this transaction is 200

[03/13/17 19:47:25.657 UTC 8E 311] pnp_resp_data: Length of data handed over 21

[03/13/17 19:47:25.657 UTC 8F 311] pnp_resp_data: session id       : 3

[03/13/17 19:47:25.657 UTC 90 311] pnp_resp_data: transaction id   : 3

[03/13/17 19:47:25.657 UTC 91 311] pnp_resp_data: status_code      : 200

[03/13/17 19:47:25.657 UTC 92 311] pnp_resp_data: status_string    : OK

[03/13/17 19:47:25.657 UTC 93 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/13/17 19:47:25.657 UTC 94 311] pnp_resp_data: content_encoding :

[03/13/17 19:47:25.657 UTC 95 311] pnp_resp_data: content_length   : 21

[03/13/17 19:47:25.657 UTC 96 311] pnp_resp_data: Location         :

[03/13/17 19:47:25.657 UTC 97 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/13/17 19:47:25.657 UTC 98 311] pnp_resp_data: Data has not been cached

[03/13/17 19:47:25.657 UTC 99 311] pnp_http_resp_data_free: pnp response data freed

[03/13/17 19:47:25.657 UTC 9A 398] pnp_httpc_send_get: HTTP send success()

[03/13/17 19:47:25.657 UTC 9B 398] send_work_req: HTTP SEND GET REQUEST SUCCESS

[03/13/17 19:47:25.657 UTC 9C 398] HA registry indicates presence of standby

[03/13/17 19:47:25.657 UTC 9D 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/13/17 19:47:25.657 UTC 9E 398] 10.stdby Disabled;

[03/13/17 19:47:26.666 UTC 9F 398] HA, config safe check [OK], for configuring[try:1]

[03/13/17 19:47:26.666 UTC A0 398] pnpa_dhcp_discovery:Configured pnp profile

[03/13/17 19:47:26.667 UTC A1 398] pnp_setup_abort:Setup abort initiated

[03/13/17 19:47:26.667 UTC A2 398] start_pnpa_discovery: PnP discovery process successful

[03/13/17 19:47:26.667 UTC A3 398] pnp_autoinstall_terminate: Terminating ip autoinstall

[03/13/17 19:47:26.667 UTC A4 398] pnp_autoinstall_terminate: Terminating DHCP autoinstall

[03/13/17 19:47:58.408 UTC A5 284] 11.stdby Disabled;

[03/13/17 19:47:58.408 UTC A6 284] 12.stdby Disabled;

[03/13/17 19:47:58.409 UTC A7 284] HA registry indicates NO standby up

[03/13/17 19:47:58.409 UTC A8 284] 13.stdby Disabled;

[03/13/17 20:01:15.011 UTC A9 284] HA, config safe check [OK], for configuring[try:0]

[03/13/17 20:01:15.327 UTC AA 176] 14.stdby Disabled;

[03/13/17 20:01:15.327 UTC AB 176] HA registry indicates NO standby up

[03/13/17 20:01:15.327 UTC AC 176] 15.stdby Disabled;

[03/13/17 20:01:16.328 UTC AD 176] HA, config safe check [OK], for configuring[try:0]

[aradford]

Hi Zak,

this looks very suspicious....

"

[03/13/17 17:15:32.908 UTC 16 398] pnpa_ntp_sync : Unable to configure NTP Server IP[10.255.72.116]

[03/13/17 17:15:32.935 UTC 2A 398] pnpa_disc_trustpool_install: NTP sync unsuccessful

[03/13/17 17:15:32.936 UTC 2B 398] 10.stdby Disabled;

Can you verify ntp server is ok and the NTP server IP address is correct.  PKI is impossible without correct ntp.

Adam

[zlantz]

Is this regarding the ntp server that the deployment switch receives from DHCP or is this pertaining to the NTP server that the controller is utilizing?

I looked at my DHCP scope options and the deployment switches should be receiving the correct NTP server which is 10.255.72.50

[penxu]

Zak,

what certificate has been installed on APIC-EM? If that certificate's issuing CA is not part of trust bundle, do not think it will work for you with port 443 as initial connection. Port 80 should work as we just install server certificate (self-signed or not) to device, then switch to HTTPs after that.

[aradford]

Hi Zak,

Is the ntp server reachable from the device?

[zlantz]

Peng Xu,

The cert was installed in the "Certificate" section under "Network Settings" and the trust pool was updated, using the gui, after installing the cert. We did have plenty of issues with getting the cert to install and had a TAC case open for some time to get the controller to take the cert.
I tried with my option 43 set to K4 and to use port 80 again and I see the same issue.

Adam,

Yes, the device can ping the ntp server

[penxu]

Zak,

Can you try with unplanned workflow? From the log, it seems device contacted to PnP sever.

[zlantz]

Device does not show up as unplanned when attempting to use the unplanned workflow. Trace below:

Switch#sh pnp trace

[03/20/17 12:52:04.274 UTC 1 398] Info: Startup config does not exists

[03/20/17 12:52:04.274 UTC 2 398] start_pnpa_discovery: PnP Discovery trial number[1]

[03/20/17 12:52:04.274 UTC 3 398] start_pnpa_discovery: Initiating PnP discovery manager

[03/20/17 12:52:04.274 UTC 4 398] pnpa_discovery_autoinstall_pid_create: waiting for autoinstall

[03/20/17 12:52:48.910 UTC 5 398] pnpa_discovery_autoinstall_pid_create:Received autoinstall complete status

[03/20/17 12:52:53.904 UTC 6 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/20/17 12:52:53.904 UTC 7 398] pnpa_autonomic_discovery: Starting autonomic discovery

[03/20/17 12:52:58.904 UTC 8 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/20/17 12:52:58.904 UTC 9 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/20/17 12:52:58.904 UTC A 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/20/17 12:52:58.904 UTC B 398] pnpa_disc_dhcp_option_43: op43 transport 1

[03/20/17 12:52:58.904 UTC C 398] pnpa_disc_dhcp_option_43: transport http

[03/20/17 12:52:58.904 UTC D 398] pnpa_validate_port_type: Port is 80

[03/20/17 12:52:58.904 UTC E 398] pnpa_disc_dhcp_option_43: op43 port 80

[03/20/17 12:52:58.905 UTC F 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/20/17 12:52:58.905 UTC 10 398] pnp_httpc_register: PnP httpc registered

[03/20/17 12:52:58.905 UTC 11 398] get_pnp_work_req_url: Port is 80

[03/20/17 12:52:58.905 UTC 12 398] pnp_httpc_send_get: url http://10.255.72.116:80/pnp/HELLO

[03/20/17 12:52:58.905 UTC 13 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/20/17 12:52:58.920 UTC 14 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/20/17 12:52:58.920 UTC 15 311] pnp_resp_data: request status Response data recieved, successfully

[03/20/17 12:52:58.920 UTC 16 311] pnp_resp_data: DATA STARTS HERE

[03/20/17 12:52:58.921 UTC 17 311] pnp_resp_data: DATA ENDS HERE

[03/20/17 12:52:58.921 UTC 18 311] pnp_resp_data: Status of this transaction is 200

[03/20/17 12:52:58.921 UTC 19 311] pnp_resp_data: Length of data handed over 21

[03/20/17 12:52:58.921 UTC 1A 311] pnp_resp_data: session id       : 3

[03/20/17 12:52:58.921 UTC 1B 311] pnp_resp_data: transaction id   : 1

[03/20/17 12:52:58.921 UTC 1C 311] pnp_resp_data: status_code      : 200

[03/20/17 12:52:58.921 UTC 1D 311] pnp_resp_data: status_string    : OK

[03/20/17 12:52:58.921 UTC 1E 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/20/17 12:52:58.922 UTC 1F 311] pnp_resp_data: content_encoding :

[03/20/17 12:52:58.922 UTC 20 311] pnp_resp_data: content_length   : 21

[03/20/17 12:52:58.922 UTC 21 311] pnp_resp_data: Location         :

[03/20/17 12:52:58.922 UTC 22 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/20/17 12:52:58.922 UTC 23 311] pnp_resp_data: Data has not been cached

[03/20/17 12:52:58.922 UTC 24 311] pnp_http_resp_data_free: pnp response data freed

[03/20/17 12:52:58.922 UTC 25 398] pnp_httpc_send_get: HTTP send success()

[03/20/17 12:52:58.923 UTC 26 398] send_work_req: HTTP SEND GET REQUEST SUCCESS

[03/20/17 12:52:58.923 UTC 27 398] HA registry indicates presence of standby

[03/20/17 12:52:58.923 UTC 28 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/20/17 12:52:58.923 UTC 29 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/20/17 12:52:58.923 UTC 2A 398] pnpa_dhcp_discovery:PnP profile config unsuccessful

[03/20/17 12:52:58.930 UTC 2B 398] pnpa_disc_dhcp_option_43: op43 strict protocol: Yes, must secure: No

[03/20/17 12:52:58.930 UTC 2C 398] pnpa_disc_dhcp_option_43: op43 profile pnp-zero-touch

[03/20/17 12:52:58.930 UTC 2D 398] pnpa_disc_dhcp_option_43: op43 ipaddr 10.255.72.116

[03/20/17 12:52:58.930 UTC 2E 398] pnpa_disc_dhcp_option_43: op43 transport 1

[03/20/17 12:52:58.930 UTC 2F 398] pnpa_disc_dhcp_option_43: transport http

[03/20/17 12:52:58.930 UTC 30 398] pnpa_validate_port_type: Port is 80

[03/20/17 12:52:58.930 UTC 31 398] pnpa_disc_dhcp_option_43: op43 port 80

[03/20/17 12:52:58.930 UTC 32 398] pnpa_validate_ip_type: op43 iptype ipv4

[03/20/17 12:52:58.930 UTC 33 398] pnp_httpc_register: PnP Already registered with httpc

[03/20/17 12:52:58.930 UTC 34 398] get_pnp_work_req_url: Port is 80

[03/20/17 12:52:58.930 UTC 35 398] pnp_httpc_send_get: url http://10.255.72.116:80/pnp/HELLO

[03/20/17 12:52:58.930 UTC 36 398] pnp_httpc_send_get: HTTP SEND SUCCESS

[03/20/17 12:52:58.935 UTC 37 311] pnp_http_resp_data_alloc: PnP response data alloc 4096 bytes

[03/20/17 12:52:58.935 UTC 38 311] pnp_resp_data: request status Response data recieved, successfully

[03/20/17 12:52:58.935 UTC 39 311] pnp_resp_data: DATA STARTS HERE

[03/20/17 12:52:58.935 UTC 3A 311] pnp_resp_data: DATA ENDS HERE

[03/20/17 12:52:58.935 UTC 3B 311] pnp_resp_data: Status of this transaction is 200

[03/20/17 12:52:58.935 UTC 3C 311] pnp_resp_data: Length of data handed over 21

[03/20/17 12:52:58.935 UTC 3D 311] pnp_resp_data: session id       : 3

[03/20/17 12:52:58.935 UTC 3E 311] pnp_resp_data: transaction id   : 2

[03/20/17 12:52:58.935 UTC 3F 311] pnp_resp_data: status_code      : 200

[03/20/17 12:52:58.935 UTC 40 311] pnp_resp_data: status_string    : OK

[03/20/17 12:52:58.935 UTC 41 311] pnp_resp_data: content_type     : application/json;charset=UTF-8

[03/20/17 12:52:58.935 UTC 42 311] pnp_resp_data: content_encoding :

[03/20/17 12:52:58.935 UTC 43 311] pnp_resp_data: content_length   : 21

[03/20/17 12:52:58.935 UTC 44 311] pnp_resp_data: Location         :

[03/20/17 12:52:58.935 UTC 45 311] pnp_resp_data: Server           : Jetty(9.0.z-SNAPSHOT)

[03/20/17 12:52:58.935 UTC 46 311] pnp_resp_data: Data has not been cached

[03/20/17 12:52:58.935 UTC 47 311] pnp_http_resp_data_free: pnp response data freed

[03/20/17 12:52:58.935 UTC 48 398] pnp_httpc_send_get: HTTP send success()

[03/20/17 12:52:58.935 UTC 49 398] send_work_req: HTTP SEND GET REQUEST SUCCESS

[03/20/17 12:52:58.935 UTC 4A 398] HA registry indicates presence of standby

[03/20/17 12:52:58.935 UTC 4B 398] HA, config safe check [NOT OK], for configuring[try:0]

[03/20/17 12:52:58.935 UTC 4C 398] HA, config safe check [NOT OK], for configuring[try:1]

[03/20/17 12:52:58.935 UTC 4D 398] pnpa_dhcp_discovery:PnP profile config unsuccessful

[03/20/17 12:53:03.934 UTC 4E 398] pnpa_dns_discovery: Starting PnP DNS discovery

[03/20/17 12:53:03.935 UTC 4F 398] pnpa_disc_dhcp_dns: domain name ***REDACTED*** on interface Vlan1400

[03/20/17 12:53:12.933 UTC 50 398] pnpa_disc_dhcp_dns:Host name address resolution failed

[03/20/17 12:53:12.933 UTC 51 398] pnpa_dns_discovery:DNS discovery not successful

[03/20/17 12:53:12.933 UTC 52 398] pnpa_dns_discovery: Starting PnP DNS discovery

[03/20/17 12:53:12.933 UTC 53 398] pnpa_disc_dhcp_dns: domain name ***REDACTED*** on interface Vlan1400

[03/20/17 12:53:12.933 UTC 54 398] pnpa_disc_dhcp_dns:Host name address resolution failed

[03/20/17 12:53:12.933 UTC 55 398] pnpa_dns_discovery:DNS discovery not successful

[03/20/17 12:53:17.936 UTC 56 398] pnpa_cco_discovery: starting CCO discovery

[03/20/17 12:53:26.933 UTC 57 398] pnpa_cco_discovery: Hostname resolution failed

[03/20/17 12:53:26.933 UTC 58 398] pnpa_cco_discovery: starting CCO discovery

[03/20/17 12:53:26.933 UTC 59 398] pnpa_cco_discovery: Hostname resolution failed

[03/20/17 12:53:31.933 UTC 5A 398] pnpa_discovery_manager: Starting NAPP

[03/20/17 12:53:31.934 UTC 5B 398] pnpa_napp_discovery: starting NAPP discovery

[03/20/17 12:53:31.934 UTC 5C 398] set_intf_state_for_napp: Setting interface state for NAPP

[03/20/17 12:53:31.934 UTC 5D 398] pnp_pxc_recv_init: enter

[03/20/17 12:53:31.934 UTC 5E 398] pnp_pxc_send_init: pnp_pxc_xmt_process created. listener_pid=284

[03/20/17 12:53:31.934 UTC 5F 176] pnp_pxc_rcv_process: Begin

[03/20/17 12:53:31.935 UTC 60 176] pnp_pxd_new_workspace: New packet workspace 0x3C3C4A04

[03/20/17 12:53:31.935 UTC 61 176] pnp_pxc_create_recv_socket: enter

[03/20/17 12:53:31.940 UTC 62 176] pnp_pxc_create_recv_socket: done

[03/20/17 12:53:31.940 UTC 63 176] pnp_pxc_rcv_loop: enter

[03/20/17 12:53:31.940 UTC 64 284] pnp_pxc_xmt_process: Entering sending loop.

[03/20/17 12:53:32.004 UTC 65 284] pnp_pxc_xmt_loop: str_port_len = 4

[03/20/17 12:53:32.004 UTC 66 284] pnp_pxc_xmt_loop: client_port_no  = 1029

[03/20/17 12:53:32.004 UTC 67 284] pnp_pxc_xmt_loop: str_client_ip_len = 7

[03/20/17 12:53:32.004 UTC 68 284] pnp_pxc_xmt_loop: pxy_client_ip = 0.0.0.0

[03/20/17 12:53:32.004 UTC 69 284] pnp_pxc_xmt_loop: String hello = OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP1213:WS-C3650-24PSOP133:1.0OP144:1029OP157:0.0.0.0

[03/20/17 12:53:32.010 UTC 6A 284] pnp_pxc_xmt_loop: sendto returns 99

[03/20/17 12:53:32.010 UTC 6B 284] pnp_pxc_xmt_loop: PROXY CLIENT: sent data = OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP1213:WS-C3650-24PSOP133:1.0OP144:1029OP157:0.0.0.0

[03/20/17 12:54:32.003 UTC 6C 284] pnp_pxc_rcv_cleanup: setting FAIL discovery

[03/20/17 12:54:32.003 UTC 6D 284] pnp_pxc_xmt_loop - Killing proxy client sending and receiving processes

[03/20/17 12:54:32.003 UTC 6E 284] send_timeout_response: Timeout status response sent for client 'PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084' : OPRESPSTATUS:OP1140:PID:WS-C3650-24PS,VID:V03,SN:FDO2007Q084OP123:1.0OP13OPTRANSS19:TRANSACTION TIMEOUTOPSTATUS33:PROXY CLIENT RETRY COUNT EXCEEDEDOPERRMSG75:Proxy client retry count exceeded. Proxy client process is no longer active

[03/20/17 12:54:32.003 UTC 6F 284] create_pnp_pxc_timeout_response_socket: Socket open succeeded

[03/20/17 12:54:32.009 UTC 70 284] destroy_pnp_pxc_timeout_response_socket: Closing socket

[03/20/17 12:54:32.009 UTC 71 284] pnp_pxc_xmt_process: Sending loop exited.

[03/20/17 12:54:32.009 UTC 72 284] pnp_pxc_xmt_cleanup: enter

[03/20/17 12:54:32.009 UTC 73 284] pnp_pxc_xmt_cleanup: Closing socket

[03/20/17 12:54:32.009 UTC 74 284] pnp_pxc_xmt_cleanup: Killing process

[03/20/17 12:54:32.009 UTC 75 398] pnp_wait_on_napp:Received NAPP complete status

[03/20/17 12:54:37.002 UTC 76 398] Info: PnP profile configuration was unsuccessful

[03/20/17 12:54:37.002 UTC 77 398] start_pnpa_discovery: PnP discovery process failed

[03/20/17 12:54:37.002 UTC 78 398] start_pnpa_discovery: User has entered console.Not retrying PnP.

[penxu]

What is your switch code version? It seems that you only waited a little bit two and half minutes before you get into console.

Can you wait a little longer for next time, say at least 6 mins?

Also, what is APIC-EM version? Can you send me your APIC-EM server certificate on APIC-EM?

[zlantz]

I actually let that switch sit for a couple of hours. I know the trace doesn't really show that, but I let it sit from 8 EST this morning all the way until until like 1030 EST.
We are using 3.7.3, which has worked in the past and had several successful prod deployments.
APIC-EM is on 1.4.0.1959

I'll dig out the cert that we used and PM it to you. We did have a TAC case when we were having issues with installing the cert. Here is that case # if you wanted to reference that and get a better picture of what was going on: SR 681437834

[ngoldwat]

Hey,

According to the release notes for PnP 1.4:

3650 --> 3.6.5E, 3.7.4.E, 16.1.3, 16.2.2, 16.3.1

3650-24PDM --> 16.2.2

3650-48FQM --> 16.2.2

Thanks

[zlantz]

Nick,

Did not work with 3.6.6 either.

[penxu]

Zak,

You can run this script on a Linux box to get pnp-service.log from APIC-EM. Then you can share with us.

Regards,

Peng