arista-eosplus/ztpserver — pull request #254 by phil-arista (2014-12-01 01:03:44+00:00)
Title: Added INFO-level logging to help explain high-level provisioning events

Closes #52

Added INFO level logging for high-level provisioning status. The majority of the existing logging is for error/warning conditions and the existing DEBUG logging provides mostly low-level information; the logging enhancements in this branch point out successful events in the zero touch provisioning process.

EG 1
Static Node - existing logging:
```
172.16.130.102 - - [21/Nov/2014 02:54:27] "GET /bootstrap HTTP/1.1" 200 40029
172.16.130.102 - - [21/Nov/2014 02:54:27] "GET /bootstrap/config HTTP/1.1" 200 181
172.16.130.102 - - [21/Nov/2014 02:54:35] "POST /nodes HTTP/1.1" 409 0
WARNING: [validators:175] 001122334455: PatternValidator warning: 'static_node' is missing optional attribute (node)
WARNING: [validators:175] 001122334455: PatternValidator warning: 'static_node' is missing optional attribute (variables)
WARNING: [controller:601] 001122334455: no node specific attributes file
172.16.130.102 - - [21/Nov/2014 02:54:35] "GET /nodes/001122334455 HTTP/1.1" 200 412
172.16.130.102 - - [21/Nov/2014 02:54:35] "GET /actions/copy_file HTTP/1.1" 200 6189
172.16.130.102 - - [21/Nov/2014 02:54:35] "GET /files/automate/ztpprep HTTP/1.1" 200 144
172.16.130.102 - - [21/Nov/2014 02:54:35] "GET /meta/files/automate/ztpprep HTTP/1.1" 200 65
172.16.130.102 - - [21/Nov/2014 02:54:36] "GET /actions/replace_config HTTP/1.1" 200 2307
172.16.130.102 - - [21/Nov/2014 02:54:36] "GET /nodes/001122334455/startup-config HTTP/1.1" 200 2219
172.16.130.102 - - [21/Nov/2014 02:54:36] "GET /meta/nodes/001122334455/startup-config HTTP/1.1" 200 66
172.16.130.20 - - [21/Nov/2014 02:56:40] "PUT /nodes/001122334455/startup-config HTTP/1.1" 200 0
```

Static Node - enhanced logging:
```
INFO: [controller:755] 172.16.130.102: node beginning ZeroTouchProvisioning
172.16.130.102 - - [21/Nov/2014 18:09:15] "GET /bootstrap HTTP/1.1" 200 40029
INFO: [controller:718] 172.16.130.102: syslog info included in bootstrap config
INFO: [controller:731] 172.16.130.102: XMPP info included in bootstrap config
172.16.130.102 - - [21/Nov/2014 18:09:15] "GET /bootstrap/config HTTP/1.1" 200 181
INFO: [controller:254] 172.16.130.102: received LLDP, SystemID, Version and Model information from node
INFO: [topology:304] 001122334455: parsing node LLDP Neighbor information
INFO: [controller:272] 172.16.130.102: successfully determined node ID(001122334455) based upon systemmac
INFO: [controller:301] 001122334455: this node already exists on the server
INFO: [controller:457] 001122334455: saved LLDP information to nodes/001122334455/.node
172.16.130.102 - - [21/Nov/2014 18:09:22] "POST /nodes HTTP/1.1" 409 0
INFO: [controller:494] 001122334455: received request for node definition
INFO: [topology:304] 001122334455: parsing node LLDP Neighbor information
INFO: [controller:535] 001122334455: topology validation is ENABLED
INFO: [controller:542] 001122334455: validating pattern file for topology validation nodes/001122334455/pattern
WARNING: [validators:175] 001122334455: PatternValidator warning: 'static_node' is missing optional attribute (node)
WARNING: [validators:175] 001122334455: PatternValidator warning: 'static_node' is missing optional attribute (variables)
INFO: [controller:552] 001122334455: evaluating node info against nodes/001122334455/pattern
WARNING: [controller:620] 001122334455: no node specific attributes file
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /nodes/001122334455 HTTP/1.1" 200 412
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /actions/copy_file HTTP/1.1" 200 6189
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /files/automate/ztpprep HTTP/1.1" 200 144
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /meta/files/automate/ztpprep HTTP/1.1" 200 65
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /actions/replace_config HTTP/1.1" 200 2307
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /nodes/001122334455/startup-config HTTP/1.1" 200 2219
172.16.130.102 - - [21/Nov/2014 18:09:23] "GET /meta/nodes/001122334455/startup-config HTTP/1.1" 200 66
```

Note that there is now a helpful log that ties the node_id to the IP Address. The logging also calls out the specific file locations that are used.

EG 2
Dynamic Node - existing logging:
```
172.16.130.100 - - [21/Nov/2014 09:19:29] "GET /bootstrap HTTP/1.1" 200 40029
172.16.130.100 - - [21/Nov/2014 09:19:29] "GET /bootstrap/config HTTP/1.1" 200 181
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'torb for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'torb for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [controller:386] 000c29665ee7: node matched 'tora for pod1' pattern in neighbordb
172.16.130.100 - - [21/Nov/2014 09:19:36] "POST /nodes HTTP/1.1" 201 0
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
WARNING: [controller:616] 000c29665ee7: no node specific attributes file
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /nodes/000c29665ee7 HTTP/1.1" 200 2660
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /actions/add_config HTTP/1.1" 200 3249
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/ma1.template HTTP/1.1" 200 60
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/system.template HTTP/1.1" 200 340
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/login.template HTTP/1.1" 200 36
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/ztpprep.template HTTP/1.1" 200 43
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/configpush.template HTTP/1.1" 200 295
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/mlag.template HTTP/1.1" 200 388
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/xmpp.template HTTP/1.1" 200 231
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/l3.template HTTP/1.1" 200 528
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/templates/bgpauto.template HTTP/1.1" 200 123
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /actions/copy_file HTTP/1.1" 200 6189
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/automate/bgpautoinf.py HTTP/1.1" 200 1451
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /meta/files/automate/bgpautoinf.py HTTP/1.1" 200 66
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /files/automate/ztpprep HTTP/1.1" 200 144
172.16.130.100 - - [21/Nov/2014 09:19:36] "GET /meta/files/automate/ztpprep HTTP/1.1" 200 65
172.16.130.50 - - [21/Nov/2014 09:21:40] "PUT /nodes/000c29665ee7/startup-config HTTP/1.1" 200 0ss
```

Dynamic Node - enhanced logging:
```
INFO: [controller:755] 172.16.130.100: node beginning ZeroTouchProvisioning
172.16.130.100 - - [21/Nov/2014 18:11:38] "GET /bootstrap HTTP/1.1" 200 40029
INFO: [controller:718] 172.16.130.100: syslog info included in bootstrap config
INFO: [controller:731] 172.16.130.100: XMPP info included in bootstrap config
172.16.130.100 - - [21/Nov/2014 18:11:38] "GET /bootstrap/config HTTP/1.1" 200 181
INFO: [controller:254] 172.16.130.100: received LLDP, SystemID, Version and Model information from node
INFO: [topology:304] 000c29665ee7: parsing node LLDP Neighbor information
INFO: [controller:272] 172.16.130.100: successfully determined node ID(000c29665ee7) based upon systemmac
INFO: [controller:330] 000c29665ee7: node does not exist on the server - will try to match node against neighbordb
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'torb for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'torb for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [controller:389] 000c29665ee7: node matched 'tora for pod1' pattern in neighbordb
INFO: [controller:394] 000c29665ee7: definition location: definitions/tora
INFO: [controller:412] 000c29665ee7: new /nodes/000c29665ee7 folder created
INFO: [controller:457] 000c29665ee7: saved LLDP information to nodes/000c29665ee7/.node
172.16.130.100 - - [21/Nov/2014 18:11:48] "POST /nodes HTTP/1.1" 201 0
INFO: [controller:494] 000c29665ee7: received request for node definition
INFO: [topology:304] 000c29665ee7: parsing node LLDP Neighbor information
INFO: [controller:535] 000c29665ee7: topology validation is ENABLED
INFO: [controller:542] 000c29665ee7: validating pattern file for topology validation nodes/000c29665ee7/pattern
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (node)
WARNING: [validators:175] 000c29665ee7: PatternValidator warning: 'tora for pod1' is missing optional attribute (variables)
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [utils:202] Ethernet1 expanded to: set(['Ethernet1'])
INFO: [controller:552] 000c29665ee7: evaluating node info against nodes/000c29665ee7/pattern
WARNING: [controller:620] 000c29665ee7: no node specific attributes file
172.16.130.100 - - [21/Nov/2014 18:11:48] "GET /nodes/000c29665ee7 HTTP/1.1" 200 2660
172.16.130.100 - - [21/Nov/2014 18:11:48] "GET /actions/add_config HTTP/1.1" 200 3249
172.16.130.100 - - [21/Nov/2014 18:11:48] "GET /files/templates/ma1.template HTTP/1.1" 200 60
172.16.130.100 - - [21/Nov/2014 18:11:48] "GET /files/templates/system.template HTTP/1.1" 200 340
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/login.template HTTP/1.1" 200 36
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/ztpprep.template HTTP/1.1" 200 43
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/configpush.template HTTP/1.1" 200 295
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/mlag.template HTTP/1.1" 200 388
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/xmpp.template HTTP/1.1" 200 231
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/l3.template HTTP/1.1" 200 528
172.16.130.100 - - [21/Nov/2014 18:11:49] "GET /files/templates/bgpauto.template HTTP/1.1" 200 123
172.16.130.100 - - [21/Nov/2014 18:11:54] "GET /actions/copy_file HTTP/1.1" 200 6189
172.16.130.100 - - [21/Nov/2014 18:11:54] "GET /files/automate/bgpautoinf.py HTTP/1.1" 200 1451
172.16.130.100 - - [21/Nov/2014 18:11:54] "GET /meta/files/automate/bgpautoinf.py HTTP/1.1" 200 66
172.16.130.100 - - [21/Nov/2014 18:11:54] "GET /files/automate/ztpprep HTTP/1.1" 200 144
172.16.130.100 - - [21/Nov/2014 18:11:54] "GET /meta/files/automate/ztpprep HTTP/1.1" 200 65
```