search

clicon / clixon-controller

Clixon network controller
Apache License 2.0
12 stars 4 forks source link

CLI sometimes exits without error #43

Closed krihal closed 6 months ago

krihal commented 9 months ago

For example:

khn@zoomie> show devices ch
khn@zoomie> show devices check

khn@zoomie:~$

No SIGSEGV etc.

olofhagsand commented 9 months ago

Cant reproduce. Any specific test? @krihal

olofhagsand commented 9 months ago

Cannot reproduce. Tried this with 100x times show devices check in test-change-both.sh (which is the only test with show device check in the CI) for both differing and equal checks. Need more context to reproduce: which devices, fail/ok check, or any other detail

krihal commented 9 months ago

I can't reproduce it but it happens from time to time. Here's a terminal log from last time. CLI exited (no crash) after the "validate push":

debian@khn-dev:~/Git/clixon-controller/test$ clixon_cli -f /usr/local/etc/controller.xml
debian@khn-dev> show conf
 devices               processes             services              |
debian@khn-dev> show configuration
debian@khn-dev> conf
debian@khn-dev> configure
debian@khn-dev[/]# set dev
 device                device-group          device-timeout
debian@khn-dev[/]# set devices de
 device                device-group          device-timeout
debian@khn-dev[/]# set devices device ad
 <name>
debian@khn-dev[/]#
debian@khn-dev[/]# set dev
 device                device-group          device-timeout
debian@khn-dev[/]# set devices de
 device                device-group          device-timeout
debian@khn-dev[/]# set devices device r1 ad
 <addr>
debian@khn-dev[/]# set devices device r1 addr 172.23.0.2
debian@khn-dev[/]# set devices device r1 conn
 NETCONF_SSH
debian@khn-dev[/]# set devices device r1 conn-type
debian@khn-dev[/]# set devices device r1 conn-type NETCONF_SSH
debian@khn-dev[/]# set devices device r1 user noc
 <user>
debian@khn-dev[/]# set devices device r1 user noc
debian@khn-dev[/]# comm
 diff                  local                 push
debian@khn-dev[/]# commit loc
debian@khn-dev[/]# commit local
debian@khn-dev[/]# exi
debian@khn-dev> conn
 close                 <name>                open                  r1                    reconnect
debian@khn-dev> connection op
debian@khn-dev> connection open
debian@khn-dev> show de
 check                 detail                diff                  <name>                r1
debian@khn-dev> show devices
Name                    State      Time                   Logmsg
=======================================================================================
r1                      OPEN       2023-09-23T03:34:16
debian@khn-dev> conf
debian@khn-dev> configure
debian@khn-dev[/]# set devices device r* config interfaces interface test config name test
debian@khn-dev[/]# set devices device r* config interfaces interface test config type iana:ethernetCsmacd
Sep 23 03:34:42: Editing configuration: application invalid-value identityref: "iana:ethernetCsmacd": prefix "iana" has no associated namespace
debian@khn-dev[/]# set devices device r* config interfaces interface test config type ethernetCsmacd
debian@khn-dev[/]# val
 local                 push
debian@khn-dev[/]# validate
debian@khn-dev[/]# val
 local                 push
debian@khn-dev[/]# validate p
debian@khn-dev[/]# validate push

debian@khn-dev:~/Git/clixon-controller/test$
krihal commented 8 months ago

Been running the CLI with "-D3 -lfcli.txt" for a while and suddently it exited. Contents of cli.txt below, afraid it don't gives any clues.

Oct 16 10:49:55: CLICON_CONFIGFILE=/usr/local/etc/controller.xml
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-controller-config@2023-01-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-config@2023-05-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-restconf@2022-08-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-inet-types@2021-02-22.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-autocli@2023-09-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-lib@2023-05-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-types@2013-07-15.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-netconf-monitoring@2010-10-04.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-metadata@2016-08-05.yang
Oct 16 10:49:55: ys_populate_feature clixon-restconf:allow-auth-none
Oct 16 10:49:55: Loading plugin '/usr/local/lib/controller/cli/controller_cli.so'
Oct 16 10:49:55: plugin_load_one file:/usr/local/lib/controller/cli/controller_cli.so function:clixon_plugin_init
Oct 16 10:49:55: plugin_load_one retval:1
Oct 16 10:49:55: clixon_pseudo_plugin pseudo yang metadata
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/as-path-filter@2023-08-07.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/as-path@2023-10-12.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/bgp-common.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/bgp-customer.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/bgp-peer-properties@2023-10-12.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/bgp-peer.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/bgp.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/clixon-controller@2023-11-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/hostname@2023-05-22.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/ibgp@2023-10-03.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/prefix-filter@2023-08-03.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/ssh-users.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/controller/test@2023-03-22.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-inet-types@2021-02-22.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-types@2013-07-15.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-netconf@2011-06-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-schema-mount@2019-01-14.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-datastores@2018-02-14.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-lib@2023-05-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-netconf-monitoring@2010-10-04.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-metadata@2016-08-05.yang
Oct 16 10:49:55: ys_populate_feature ietf-netconf:candidate
Oct 16 10:49:55: ys_populate_feature ietf-netconf:validate
Oct 16 10:49:55: ys_populate_feature ietf-netconf:startup
Oct 16 10:49:55: ys_populate_feature ietf-netconf:xpath
Oct 16 10:49:55: ietf_yang_metadata_extension_cb Enabled extension:ietf-yang-metadata:annotation:creator
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-yang-library@2019-01-04.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/clixon-rfc5277@2008-07-01.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-list-pagination@2022-07-24.yang
Oct 16 10:49:55: ietf_yang_metadata_extension_cb Enabled extension:ietf-yang-metadata:annotation:remaining
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-list-pagination-nc@2022-07-24.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-netconf-nmda@2019-01-07.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-origin@2018-02-14.yang
Oct 16 10:49:55: yang_parse_filename /usr/local/share/clixon/ietf-netconf-with-defaults@2011-06-01.yang
Oct 16 10:49:55: ietf_yang_metadata_extension_cb Enabled extension:ietf-yang-metadata:annotation:origin
Oct 16 10:49:55: autocli_start
Oct 16 10:49:55: yang2cli_grouping Generated auto-cli for grouping:teardown
Oct 16 10:49:55: yang2cli_grouping command: teardown-idle-timeout
...skipping...
Oct 18 10:58:28: CLICON_CLI_TAB_MODE =   "0"
Oct 18 10:58:28: CLICON_XMLDB_FORMAT =   "xml"
Oct 18 10:58:28: CLICON_YANG_LIBRARY =   "true"
Oct 18 10:58:28: CLICON_STARTUP_MODE =   "init"
Oct 18 10:58:28: CLICON_XMLDB_PRETTY =   "true"
Oct 18 10:58:28: CLICON_YANG_AUGMENT_ACCEPT_BROKEN =     "false"
Oct 18 10:58:28: CLICON_XML_CHANGELOG =  "false"
Oct 18 10:58:28: CLICON_CONFIG_EXTEND =  "clixon-controller-config"
Oct 18 10:58:28: CLICON_CLI_HIST_FILE =  "~/.clixon_cli_history"
Oct 18 10:58:28: CLICON_YANG_MAIN_DIR =  "/usr/local/share/clixon/controller"
Oct 18 10:58:28: CLICON_MODULE_SET_ID =  "0"
Oct 18 10:58:28: CLICON_CLI_BUF_START =  "256"
Oct 18 10:58:28: CLICON_RESTCONF_USER =  "www-data"
Oct 18 10:58:28: CLICON_CLI_HIST_SIZE =  "300"
Oct 18 10:58:28: CLICON_BACKEND_REGEXP =         "(.so)$"
Oct 18 10:58:28: CLICON_NETCONF_MESSAGE_ID_OPTIONAL =    "false"
Oct 18 10:58:28: CLICON_XMLDB_MODSTATE =         "false"
Oct 18 10:58:28: CLICON_BACKEND_PIDFILE =        "/usr/local/var/controller.pidfile"
Oct 18 10:58:28: CLICON_RESTCONF_STARTUP_DONTUPDATE =    "false"
Oct 18 10:58:28: CLICON_DATASTORE_CACHE =        "cache"
Oct 18 10:58:28: CLICON_ANONYMOUS_USER =         "anonymous"
Oct 18 10:58:28: CLICON_SNMP_AGENT_SOCK =        "unix:/tmp/clixon_snmp.sock"
Oct 18 10:58:28: CLICON_NACM_CREDENTIALS =       "except"
Oct 18 10:58:28: CLICON_STREAM_RETENTION =       "3600"
Oct 18 10:58:28: CLICON_LOG_STRING_LIMIT =       "0"
Oct 18 10:58:28: CLICON_CLI_LINESCROLLING =      "1"
Oct 18 10:58:28: CLICON_CLI_LINES_DEFAULT =      "24"
Oct 18 10:58:28: CLICON_CLI_BUF_THRESHOLD =      "65536"
Oct 18 10:58:28: CONTROLLER_PYAPI_PIDFILE =      "/tmp/clixon_server.pid"
Oct 18 10:58:28: CLICON_YANG_SCHEMA_MOUNT =      "true"
Oct 18 10:58:28: CLICON_SOCK =   "/usr/local/var/controller.sock"
Oct 18 10:58:28: CLICON_RESTCONF_API_ROOT =      "/restconf"
Oct 18 10:58:28: CLICON_BACKEND_PRIVILEGES =     "none"
Oct 18 10:58:28: CLICON_CLI_EXPAND_LEAFREF =     "false"
Oct 18 10:58:28: CONTROLLER_ACTION_COMMAND =     "/usr/local/bin/clixon_server.py -f /usr/local/etc/controller.xml -F"
Oct 18 10:58:28: CLICON_NETCONF_MONITORING =     "true"
Oct 18 10:58:28: CLICON_VALIDATE_STATE_XML =     "true"
Oct 18 10:58:28: CLICON_RESTCONF_INSTALLDIR =    "/usr/local/sbin"
Oct 18 10:58:28: CLICON_RESTCONF_PRIVILEGES =    "drop_perm"
Oct 18 10:58:28: CLICON_YANG_DIR =       "/usr/local/share/clixon"
Oct 18 10:58:28: CLICON_FEATURE =        "clixon-restconf:allow-auth-none"
Oct 18 10:58:28: CLICON_FEATURE =        "ietf-netconf:candidate"
Oct 18 10:58:28: CLICON_FEATURE =        "ietf-netconf:startup"
Oct 18 10:58:28: CLICON_FEATURE =        "ietf-netconf:validate"
Oct 18 10:58:28: CLICON_FEATURE =        "ietf-netconf:xpath"
Oct 18 10:58:32: clicon_parse result:1 command: "configure"
Oct 18 10:58:33: clicon_parse result:1 command: "commit diff"
Oct 18 10:58:33: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" username="debian" message-id="42"><controller-commit xmlns="http://clicon.org/controller"><device>*</device><push>NONE</push><actions>CHANGE</actions><source>ds:candidate</source></controller-commit></rpc>
Oct 18 10:58:33: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><tid xmlns="http://clicon.org/controller">36</tid></rpc-reply>
Oct 18 10:58:33: transaction_notification_poll tid:36
krihal commented 8 months ago

And again:

Oct 16 10:49:55: autocli_start
Oct 16 10:49:55: yang2cli_grouping Generated auto-cli for grouping:teardown
Oct 16 10:49:55: yang2cli_grouping command: teardown-idle-timeout
...skipping...
:username="debian" xmlns:cl="http://clicon.org/lib" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="42"><get-config><source><candidate/></source><nc:filter nc:type="xpath" nc:select="/ctrl:services/ctrl:properties/bgp:bgp-peer/bgp:exchange-points/bgp:name" xmlns:ctrl="http://clicon.org/controller" xmlns:bgp="http://nordu.net/ns/ncs/bgp"/></get-config></rpc>
Oct 18 11:06:30: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><data><services xmlns="http://clicon.org/controller"><properties><bgp-peer xmlns="http://nordu.net/ns/ncs/bgp"><exchange-points><name>test</name></exchange-points></bgp-peer></properties></services></data></rpc-reply>
Oct 18 11:06:30: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" cl:username="debian" xmlns:cl="http://clicon.org/lib" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="42"><get-config><source><candidate/></source><nc:filter nc:type="xpath" nc:select="/ctrl:services/ctrl:properties/bgp:bgp-peer/bgp:exchange-points/bgp:name" xmlns:ctrl="http://clicon.org/controller" xmlns:bgp="http://nordu.net/ns/ncs/bgp"/></get-config></rpc>
Oct 18 11:06:30: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><data><services xmlns="http://clicon.org/controller"><properties><bgp-peer xmlns="http://nordu.net/ns/ncs/bgp"><exchange-points><name>test</name></exchange-points></bgp-peer></properties></services></data></rpc-reply>
Oct 18 11:06:30: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" cl:username="debian" xmlns:cl="http://clicon.org/lib" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="42"><get-config><source><candidate/></source><nc:filter nc:type="xpath" nc:select="/ctrl:services/ctrl:properties/bgp:bgp-peer/bgp:exchange-points[bgp:name='test']/bgp:routing-instance" xmlns:ctrl="http://clicon.org/controller" xmlns:bgp="http://nordu.net/ns/ncs/bgp"/></get-config></rpc>
Oct 18 11:06:30: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><data/></rpc-reply>
Oct 18 11:06:32: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" cl:username="debian" xmlns:cl="http://clicon.org/lib" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="42"><get-config><source><candidate/></source><nc:filter nc:type="xpath" nc:select="/ctrl:services/ctrl:properties/bgp:bgp-peer/bgp:exchange-points/bgp:name" xmlns:ctrl="http://clicon.org/controller" xmlns:bgp="http://nordu.net/ns/ncs/bgp"/></get-config></rpc>
Oct 18 11:06:32: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><data><services xmlns="http://clicon.org/controller"><properties><bgp-peer xmlns="http://nordu.net/ns/ncs/bgp"><exchange-points><name>test</name></exchange-points></bgp-peer></properties></services></data></rpc-reply>
Oct 18 11:06:32: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" cl:username="debian" xmlns:cl="http://clicon.org/lib" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="42"><get-config><source><candidate/></source><nc:filter nc:type="xpath" nc:select="/ctrl:services/ctrl:properties/bgp:bgp-peer/bgp:exchange-points[bgp:name='test']/bgp:routing-instance" xmlns:ctrl="http://clicon.org/controller" xmlns:bgp="http://nordu.net/ns/ncs/bgp"/></get-config></rpc>
Oct 18 11:06:32: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><data/></rpc-reply>
Oct 18 11:06:32: clicon_parse result:1 command: "set services properties bgp-peer exchange-points test routing-instance test"
Oct 18 11:06:32: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" cl:username="debian" xmlns:cl="http://clicon.org/lib" message-id="42"><edit-config><target><candidate/></target><default-operation>none</default-operation><config><services xmlns="http://clicon.org/controller"><properties><bgp-peer xmlns="http://nordu.net/ns/ncs/bgp"><exchange-points><name>test</name><routing-instance nc:operation="merge">test</routing-instance></exchange-points></bgp-peer></properties></services></config></edit-config></rpc>
Oct 18 11:06:32: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><ok/></rpc-reply>
Oct 18 11:06:34: clicon_parse result:1 command: "commit"
Oct 18 11:06:34: Send [/usr/local/var/controller.sock]: <rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" username="debian" message-id="42"><controller-commit xmlns="http://clicon.org/controller"><device>*</device><push>COMMIT</push><actions>CHANGE</actions><source>ds:candidate</source></controller-commit></rpc>
Oct 18 11:06:34: Recv [/usr/local/var/controller.sock]: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><tid xmlns="http://clicon.org/controller">2</tid></rpc-reply>
Oct 18 11:06:34: transaction_notification_poll tid:2
olofhagsand commented 8 months ago

It seems this is the last log-line before exit:

Oct 18 10:58:33: transaction_notification_poll tid:36

There are a couple of scenarios:

  1. If an error occurs it should be followed by a transaction_notification_poll -1 and exit. But the log seems to end before that?
  2. If OK it should have log-line transaction_notification_poll 0 and continue.
  3. Or it could continue waiting for another notification, without any further logs. But it should not exit

Have added some more logs for case 3. Can you please collect this extended debug data in the case it happens again?

krihal commented 7 months ago

clixon_cli_strace.txt

Strace.

krihal commented 6 months ago

Haven't seen for a while, closing.