cli: netconf-config-change notification parsing fails due to a too-strict instance-identifier validation

[jktjkt]

I'm using the latest devel of liyang/libnetconf2/netopeer2-cli on the client. The server version is a random snapshot of these from April/May. A certain sequence of edit-config operations along with a catch-all notification subscribe on the client causes the client to error due to allegedly required entities in the notification about the edit-config.

Here's a relevant snippet of my YANG:

    container configuration {
      list channel {
        key "center-frequency";

        leaf center-frequency {
          type leafref {
            path "../../../channel-plan/channel/center-frequency";
          }
        }

        leaf mode {
          type pass-mode;
          mandatory true;
          description "How to route the optical signal between the INPUT, ADD and OUTPUT ports";
        }

        leaf voa-attenuation {
          when "../mode = 'ADD' or ../mode = 'PASS'";
          type attenuation;
          mandatory true;
          description "Attenuation of the VOA in dB";
        }

        leaf description {
          type string;
          description "Free-text description. Can be used to add a local remark by an administrator
          about the purpose or destination of this channel, etc.";
        }

        container min-level-input {
          presence true;
          uses channel-threshold;
          description "Alarm configuration for power at the INPUT port";
        }
      }
    }

Here's the log of actions from the CLI:

> connect ...
...
> subscribe
OK
> verb 3
> edit-config --target=running --config=/home/jkt/work/cesnet/gerrit/CzechLight/cla-sysrepo/conf-53-thr-0.xml
ly VERBOSE: Resolving unresolved data nodes and their constraints...
ly VERBOSE: All data nodes and constraints resolved.
nc DEBUG: Session 5: sending message:

#542


[2017/09/13 15:43:31.944345, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2017/09/13 15:43:31.944400, 3] packet_send2:  packet: wrote [len=28,padding=12,comp=15,payload=15]
[2017/09/13 15:43:31.944416, 3] channel_write_common:  channel_write wrote 6 bytes
nc DEBUG: Session 5: sending message:
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="3"><edit-config xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><target><running/></target><config><roadm xmlns="http://czechlight.cesnet.cz/netconf/roadm/v2">
  <configuration>
    <channel>
      <center-frequency>195300</center-frequency>
      <mode>PASS</mode>
      <voa-attenuation>0.0</voa-attenuation>
      <min-level-input>
        <critical-level>0.0</critical-level>
      </min-level-input>
    </channel>
  </configuration>
</roadm>
</config></edit-config></rpc>

[2017/09/13 15:43:31.944475, 3] packet_send2:  packet: wrote [len=556,padding=4,comp=551,payload=551]
[2017/09/13 15:43:31.944505, 3] channel_write_common:  channel_write wrote 542 bytes
[2017/09/13 15:43:31.944523, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
nc DEBUG: Session 5: sending message:

##


[2017/09/13 15:43:31.944556, 3] packet_send2:  packet: wrote [len=28,padding=14,comp=13,payload=13]
[2017/09/13 15:43:31.944574, 3] channel_write_common:  channel_write wrote 4 bytes
[2017/09/13 15:43:31.944589, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2017/09/13 15:43:33.261214, 3] ssh_packet_socket_callback:  packet: read type 94 [len=28,padding=13,comp=14,payload=14]
[2017/09/13 15:43:33.261274, 3] ssh_packet_process:  Dispatching handler for packet type 94
[2017/09/13 15:43:33.261373, 3] channel_rcv_data:  Channel receiving 5 bytes data in 0 (local win=1274452 remote win=1279015)
[2017/09/13 15:43:33.261400, 3] channel_default_bufferize:  placing 5 bytes into channel buffer (stderr=0)
[2017/09/13 15:43:33.261425, 3] channel_rcv_data:  Channel windows are now (local win=1274447 remote win=1279015)
[2017/09/13 15:43:33.261473, 3] ssh_channel_read_timeout:  Read (1) buffered : 5 bytes. Window: 1274447
[2017/09/13 15:43:33.261533, 3] ssh_channel_read_timeout:  Read (1) buffered : 4 bytes. Window: 1274447
[2017/09/13 15:43:33.261562, 3] ssh_channel_read_timeout:  Read (1) buffered : 3 bytes. Window: 1274447
[2017/09/13 15:43:33.261586, 3] ssh_channel_read_timeout:  Read (1) buffered : 2 bytes. Window: 1274447
[2017/09/13 15:43:33.261610, 3] ssh_channel_read_timeout:  Read (1) buffered : 1 bytes. Window: 1274447
[2017/09/13 15:43:33.261630, 3] ssh_channel_read_timeout:  Read (91) buffered : 0 bytes. Window: 1274447
[2017/09/13 15:43:33.261711, 3] ssh_packet_socket_callback:  packet: read type 94 [len=108,padding=7,comp=100,payload=100]
[2017/09/13 15:43:33.261732, 3] ssh_packet_process:  Dispatching handler for packet type 94
[2017/09/13 15:43:33.261752, 3] channel_rcv_data:  Channel receiving 91 bytes data in 0 (local win=1274447 remote win=1279015)
[2017/09/13 15:43:33.261769, 3] channel_default_bufferize:  placing 91 bytes into channel buffer (stderr=0)
[2017/09/13 15:43:33.261786, 3] channel_rcv_data:  Channel windows are now (local win=1274356 remote win=1279015)
[2017/09/13 15:43:33.261807, 3] ssh_packet_socket_callback:  Processing 64 bytes left in socket buffer
[2017/09/13 15:43:33.261851, 3] ssh_packet_socket_callback:  packet: read type 94 [len=28,padding=14,comp=13,payload=13]
[2017/09/13 15:43:33.261868, 3] ssh_packet_process:  Dispatching handler for packet type 94
[2017/09/13 15:43:33.261890, 3] channel_rcv_data:  Channel receiving 4 bytes data in 0 (local win=1274356 remote win=1279015)
[2017/09/13 15:43:33.261908, 3] channel_default_bufferize:  placing 4 bytes into channel buffer (stderr=0)
[2017/09/13 15:43:33.261925, 3] channel_rcv_data:  Channel windows are now (local win=1274352 remote win=1279015)
[2017/09/13 15:43:33.261949, 3] ssh_channel_read_timeout:  Read (1) buffered : 4 bytes. Window: 1274352
[2017/09/13 15:43:33.261966, 3] ssh_channel_read_timeout:  Read (1) buffered : 3 bytes. Window: 1274352
[2017/09/13 15:43:33.261983, 3] ssh_channel_read_timeout:  Read (1) buffered : 2 bytes. Window: 1274352
[2017/09/13 15:43:33.261999, 3] ssh_channel_read_timeout:  Read (1) buffered : 1 bytes. Window: 1274352
nc DEBUG: Session 5: received message:
<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="3"><ok/></rpc-reply>

OK
[edit-config: took 1321.214698ms]
> 
nc DEBUG: Session 5: received message:
<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0"><eventTime>2017-09-13T13:43:33Z</eventTime><netconf-config-change xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-notifications"><changed-by><session-id>1458460032</session-id><username>root</username></changed-by><datastore>running</datastore><edit><target xmlns:czechlight-roadm-v2="http://czechlight.cesnet.cz/netconf/roadm/v2">/czechlight-roadm-v2:roadm/czechlight-roadm-v2:configuration/czechlight-roadm-v2:channel[czechlight-roadm-v2:center-frequency='195300']/czechlight-roadm-v2:mode</target><operation>merge</operation></edit><edit><target xmlns:czechlight-roadm-v2="http://czechlight.cesnet.cz/netconf/roadm/v2">/czechlight-roadm-v2:roadm/czechlight-roadm-v2:configuration/czechlight-roadm-v2:channel[czechlight-roadm-v2:center-frequency='195300']/czechlight-roadm-v2:min-level-input/czechlight-roadm-v2:critical-level</target><operation>merge</operation></edit></netconf-config-change></notification>

> 
ly VERBOSE: Resolving unresolved data nodes and their constraints...
> 
ly ERROR: Required instance of "/czechlight-roadm-v2:roadm/configuration/channel[center-frequency='195300']/mode" does not exists. (/ietf-netconf-notifications:netconf-config-change/edit[1]/target)
> 
nc ERROR: Session 5: failed to parse a new notification.
> 
nc VERBOSE: Session 5: notification thread exit.

As you can see, the CLI stops notification processing once it receives the following response:

<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0">
    <eventTime>2017-09-13T13:43:33Z</eventTime>
    <netconf-config-change xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-notifications">
        <changed-by>
            <session-id>1458460032</session-id>
            <username>root</username>
        </changed-by>
        <datastore>running</datastore>
        <edit>
            <target xmlns:czechlight-roadm-v2="http://czechlight.cesnet.cz/netconf/roadm/v2">/czechlight-roadm-v2:roadm/czechlight-roadm-v2:configuration/czechlight-roadm-v2:channel[czechlight-roadm-v2:center-frequency='195300']/czechlight-roadm-v2:mode</target>
            <operation>merge</operation>
        </edit>
        <edit>
            <target xmlns:czechlight-roadm-v2="http://czechlight.cesnet.cz/netconf/roadm/v2">/czechlight-roadm-v2:roadm/czechlight-roadm-v2:configuration/czechlight-roadm-v2:channel[czechlight-roadm-v2:center-frequency='195300']/czechlight-roadm-v2:min-level-input/czechlight-roadm-v2:critical-level</target>
            <operation>merge</operation>
        </edit>
    </netconf-config-change>
</notification>

I haven't tested (yet) whether I get a similar behavior with the latest server (I'll report back later). I also don't know if the notification as created by that version of the server is correct or not. However, I think that the client cannot have a data-race-free access to the old configuration anyway, so attempting to verify whether this instance-identifier actually points to an existing node is probably a wrong thing to do when handling notifications.

From my point of view, this is a low-priority issue because we are using the CLI just for some ad-hoc testing. It does not block us in any substantial way right now.

[michalvasko]

Hi,
it was not meant to be fully validated, it just failed to be recognized that way and it was all caused by a rather trivial mistake, should be fixed now.

Regards,
Michal