cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
524
Views
3
Helpful
7
Replies

Python VM started but not running

Noel Cantenot
Level 1
Level 1

Hello,
Running NSO 6.3, python 3.12, everything worked fine until this morning, when reloading packages, I got this result:

admin@ncs# packages reload
reload-result {
    package cfs-vlan
    result true
}
reload-result {
    package cisco-nx-cli-5.25
    result true
}
reload-result {
    package rfs-router-intf
    result false
    info Python VM failed to start
}
admin@ncs#

Both packages cfs-vlan et rfs-router-intf have python template, but only cfs-vlan runs its Python VM.
I can see in logs that cfs-vlan VM is started and running, whereas rfs-router-intf is started, but not running.

[root@nso-dev-nc-nso6 logs]# more ncs-python-vm-cfs-vlan.log
<INFO> 30-Aug-2024::12:33:04.457 cfs-vlan MainThread: - Python 3.12.1 (main, May  3 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3.0.1)]
<INFO> 30-Aug-2024::12:33:04.461 cfs-vlan MainThread: - Using callpoint-model: threading
<INFO> 30-Aug-2024::12:33:04.461 cfs-vlan MainThread: - Starting...
<INFO> 30-Aug-2024::12:33:04.462 cfs-vlan MainThread: - Started
<INFO> 30-Aug-2024::12:33:04.470 cfs-vlan ComponentThread:main: - Main RUNNING
[root@nso-dev-nc-nso6 logs]#
[root@nso-dev-nc-nso6 logs]# more ncs-python-vm-rfs-router-intf.log
<INFO> 30-Aug-2024::12:33:04.456 rfs-router-intf MainThread: - Python 3.12.1 (main, May  3 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3.0.1)]
<INFO> 30-Aug-2024::12:33:04.459 rfs-router-intf MainThread: - Using callpoint-model: threading
<INFO> 30-Aug-2024::12:33:04.459 rfs-router-intf MainThread: - Starting...
<INFO> 30-Aug-2024::12:33:04.460 rfs-router-intf MainThread: - Started
[root@nso-dev-nc-nso6 logs]#

Which is confirmed by ps:

[root@nso-dev-nc-nso6 logs]# ps -ef | grep python
root        7121    7007  0 10:37 ?        00:00:00 /root/.vscode-server/extensions/ms-python.python-2024.12.3-linux-x64/python-env-tools/bin/pet server
root        7426    7007  0 10:37 ?        00:00:08 /root/.vscode-server/cli/servers/Stable-fee1edb8d6d72a0ddff41e5f71a671c23ed924b9/server/node /root/.vscode-server/extensions/ms-python.vscode-pylance-2024.8.2/dist/server.bundle.js --cancellationReceive=file:cf685b5b1eb5fe86ac5d6c71631069a2f185e30de8 --experimentalserver --node-ipc --clientProcessId=7007
root        8732    6006  0 12:33 ?        00:00:00 python3 -u /root/nso-6.3/src/ncs/pyapi/ncs_pyvm/startup.py -l info -f ./logs/ncs-python-vm -i cfs-vlan -s alarm
root        8795    7564  0 12:35 pts/1    00:00:00 grep --color=auto python
[root@nso-dev-nc-nso6 logs]#

There is no lack of space on disks nor RAM.

I read that there is this kind of issue with older NSO/Python version, but I'm up to date with NSO 6.3 and python 3.12.

Any idea of what to check ?

Regards.

1 Accepted Solution

Accepted Solutions

rogaglia
Cisco Employee
Cisco Employee

I think we are getting close. I am not sure what your code is doing but yes NSO runs the registration class at the time it loads the package. The class is pointed at the package-meta-data.xml file.

See example from skeleton package where the Main class is executed at loading time:

 

# -*- mode: python; python-indent: 4 -*-
import ncs
from ncs.application import Service


# ------------------------
# SERVICE CALLBACK EXAMPLE
# ------------------------
class ServiceCallbacks(Service):

    # The create() callback is invoked inside NCS FASTMAP and
    # must always exist.
    .create
    def cb_create(self, tctx, root, service, proplist):
        self.log.info('Service create(service=', service._path, ')')

        vars = ncs.template.Variables()
        vars.add('DUMMY', '127.0.0.1')
        template = ncs.template.Template(service)
        template.apply('interface_mtu-template', vars)

    # The pre_modification() and post_modification() callbacks are optional,
    # and are invoked outside FASTMAP. pre_modification() is invoked before
    # create, update, or delete of the service, as indicated by the enum
    # ncs_service_operation op parameter. Conversely
    # post_modification() is invoked after create, update, or delete
    # of the service. These functions can be useful e.g. for
    # allocations that should be stored and existing also when the
    # service instance is removed.

    # .pre_modification
    # def cb_pre_modification(self, tctx, op, kp, root, proplist):
    #     self.log.info('Service premod(service=', kp, ')')

    # .post_modification
    # def cb_post_modification(self, tctx, op, kp, root, proplist):
    #     self.log.info('Service postmod(service=', kp, ')')


# ---------------------------------------------
# COMPONENT THREAD THAT WILL BE STARTED BY NCS.
# ---------------------------------------------
class Main(ncs.application.Application):
    def setup(self):
        # The application class sets up logging for us. It is accessible
        # through 'self.log' and is a ncs.log.Log instance.
        self.log.info('Main RUNNING')

        # Service callbacks require a registration for a 'service point',
        # as specified in the corresponding data model.
        #
        self.register_service('interface_mtu-servicepoint', ServiceCallbacks)

        # If we registered any callback(s) above, the Application class
        # took care of creating a daemon (related to the service/action point).

        # When this setup method is finished, all registrations are
        # considered done and the application is 'started'.

    def teardown(self):
        # When the application is finished (which would happen if NCS went
        # down, packages were reloaded or some error occurred) this teardown
        # method will be called.

        self.log.info('Main FINISHED')

 

The package-meta-data.xml points NSO to that class:

 
  <component>
    <name>main</name>
    <application>
      <python-class-name>interface_mtu.main.Main</python-class-name>
    </application>
  </component>

View solution in original post

7 Replies 7

Noel Cantenot
Level 1
Level 1

Looking deeper in the logs, it seems the last service deployment started 29 Aug (yesterday) and terminated 30 Aug (today). And after that, the VM does not start running anymore...

<INFO> 29-Aug-2024::08:48:08.41 rfs-router-intf ncs-dp-193457-rfs-router-intf:main:0-9-th-14519: - vars: [('DESCRIPTION', "'NSO - RFS -vlan 10'"), ('VLAN_ID', "'10'"), ('IP_ADD', "'10.1.1.1/24'")]
<INFO> 29-Aug-2024::08:48:08.46 rfs-router-intf ncs-dp-193457-rfs-router-intf:main:0-9-th-14519: - vars: [('DESCRIPTION', "'NSO - CFS-RFS - *** vlan 100 ***'"), ('VLAN_ID', "'100'"), ('IP_ADD', "'100.1.1.1/24'")]
<INFO> 29-Aug-2024::08:48:08.51 rfs-router-intf ncs-dp-193457-rfs-router-intf:main:0-9-th-14519: - vars: [('DESCRIPTION', "'NSO - CFS-RFS - *** vlan 200 ***'"), ('VLAN_ID', "'200'"), ('IP_ADD', "'200.1.1.1/24'")]
<INFO> 30-Aug-2024::10:26:09.963 rfs-router-intf MainThread: - Exiting...
<INFO> 30-Aug-2024::10:26:09.965 rfs-router-intf MainThread: - joining ComponentThread rfs_router_intf.main.Main...
<INFO> 30-Aug-2024::10:26:09.965 rfs-router-intf ComponentThread:main: - Main FINISHED
<INFO> 30-Aug-2024::10:26:09.965 rfs-router-intf MainThread: - joined ComponentThread rfs_router_intf.main.Main
<INFO> 30-Aug-2024::10:26:09.965 rfs-router-intf MainThread: - Exited
<INFO> 30-Aug-2024::10:26:09.965 rfs-router-intf MainThread: - Goodbye cruel world...
<INFO> 30-Aug-2024::10:26:10.71 rfs-router-intf MainThread: - Python 3.12.1 (main, May  3 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3.0.1)]
<INFO> 30-Aug-2024::10:26:10.74 rfs-router-intf MainThread: - Using callpoint-model: threading
<INFO> 30-Aug-2024::10:26:10.74 rfs-router-intf MainThread: - Starting...
<INFO> 30-Aug-2024::10:26:10.75 rfs-router-intf MainThread: - Started
<INFO> 30-Aug-2024::10:27:29.183 rfs-router-intf MainThread: - Python 3.12.1 (main, May  3 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3.0.1)]
<INFO> 30-Aug-2024::10:27:29.187 rfs-router-intf MainThread: - Using callpoint-model: threading
<INFO> 30-Aug-2024::10:27:29.187 rfs-router-intf MainThread: - Starting...
<INFO> 30-Aug-2024::10:27:29.188 rfs-router-intf MainThread: - Started

 

rogaglia
Cisco Employee
Cisco Employee

Have you also checked the ncs-python-vm.log log and the developer.log? One issue that I had in the past are problems with the package-meta-data.xml file. Just a hint.

Hi,looking at ncs-python-vm.log I can see this:

[root@nso-dev-nc-nso6 logs]# more ncs-python-vm.log
<INFO> 3-Sep-2024::12:05:02.225 nso-dev-nc-nso6 ncs[17080]: rfs-router-intf :: start
> /root/nso-instance-NOEL/state/packages-in-use/1/rfs-router-intf/python/rfs_router_intf/main.py(74)<module>()
-> print ("stop")
<INFO> 3-Sep-2024::12:05:32.146 nso-dev-nc-nso6 ncs[17080]: rfs-router-intf :: (Pdb) <INFO> 3-Sep-2024::12:05:32.146 nso-dev-nc-nso6 ncs[17080]: Got EXIT on Port= #Port<0.1474>

On python file, I have this:

line 73  print ("start")
line 74  breakpoint()
line 75  print ("stop")

I remove line 74 and the package loads !

But, I want to use remote debug with vscode, so I added at the begening of python file:

  import debugpy
  debugpy.listen(("172.25.74.27",5678))
  print ("waiting for debugger...")
  debugpy.wait_for_client()  # blocks execution until client is attached

And when I relaod package, same problem, VM failed to start !
Look at the log :

<INFO> 3-Sep-2024::12:36:06.928 nso-dev-nc-nso6 ncs[17080]: Started PyVM: <<"rfs-router-intf">> , Port=#Port<0.2992> , OSpid="19008"
<INFO> 3-Sep-2024::12:36:06.931 nso-dev-nc-nso6 ncs[17080]: rfs-router-intf :: Starting python3 -u /root/nso-6.3/src/ncs/pyapi/ncs_pyvm/startup.py -l info -f ./logs/ncs-python-vm -i rfs-router-intf -s alarm
<INFO> 3-Sep-2024::12:36:07.064 nso-dev-nc-nso6 ncs[17080]: rfs-router-intf :: 0.00s - Debugger warning: It seems that frozen modules are being used, which may
0.00s - make the debugger miss breakpoints. Please pass -Xfrozen_modules=off
0.00s - to python to disable frozen modules.
0.00s - Note: Debugging will proceed. Set PYDEVD_DISABLE_FILE_VALIDATION=1 to disable this validation.
<INFO> 3-Sep-2024::12:36:07.337 nso-dev-nc-nso6 ncs[17080]: rfs-router-intf :: Attente de la connexion du debuger...
<INFO> 3-Sep-2024::12:36:36.955 nso-dev-nc-nso6 ncs[17080]: Got EXIT on Port= #Port<0.2992>
[root@nso-dev-nc-nso6 logs]#

Same kind of issue !!

Does NSO execute the python code when loading packages ???

rogaglia
Cisco Employee
Cisco Employee

I think we are getting close. I am not sure what your code is doing but yes NSO runs the registration class at the time it loads the package. The class is pointed at the package-meta-data.xml file.

See example from skeleton package where the Main class is executed at loading time:

 

# -*- mode: python; python-indent: 4 -*-
import ncs
from ncs.application import Service


# ------------------------
# SERVICE CALLBACK EXAMPLE
# ------------------------
class ServiceCallbacks(Service):

    # The create() callback is invoked inside NCS FASTMAP and
    # must always exist.
    .create
    def cb_create(self, tctx, root, service, proplist):
        self.log.info('Service create(service=', service._path, ')')

        vars = ncs.template.Variables()
        vars.add('DUMMY', '127.0.0.1')
        template = ncs.template.Template(service)
        template.apply('interface_mtu-template', vars)

    # The pre_modification() and post_modification() callbacks are optional,
    # and are invoked outside FASTMAP. pre_modification() is invoked before
    # create, update, or delete of the service, as indicated by the enum
    # ncs_service_operation op parameter. Conversely
    # post_modification() is invoked after create, update, or delete
    # of the service. These functions can be useful e.g. for
    # allocations that should be stored and existing also when the
    # service instance is removed.

    # .pre_modification
    # def cb_pre_modification(self, tctx, op, kp, root, proplist):
    #     self.log.info('Service premod(service=', kp, ')')

    # .post_modification
    # def cb_post_modification(self, tctx, op, kp, root, proplist):
    #     self.log.info('Service postmod(service=', kp, ')')


# ---------------------------------------------
# COMPONENT THREAD THAT WILL BE STARTED BY NCS.
# ---------------------------------------------
class Main(ncs.application.Application):
    def setup(self):
        # The application class sets up logging for us. It is accessible
        # through 'self.log' and is a ncs.log.Log instance.
        self.log.info('Main RUNNING')

        # Service callbacks require a registration for a 'service point',
        # as specified in the corresponding data model.
        #
        self.register_service('interface_mtu-servicepoint', ServiceCallbacks)

        # If we registered any callback(s) above, the Application class
        # took care of creating a daemon (related to the service/action point).

        # When this setup method is finished, all registrations are
        # considered done and the application is 'started'.

    def teardown(self):
        # When the application is finished (which would happen if NCS went
        # down, packages were reloaded or some error occurred) this teardown
        # method will be called.

        self.log.info('Main FINISHED')

 

The package-meta-data.xml points NSO to that class:

 
  <component>
    <name>main</name>
    <application>
      <python-class-name>interface_mtu.main.Main</python-class-name>
    </application>
  </component>

OK, my "breakpoint()" was out of the class (at the end of the file, it was a test), as are the lines for debugger waiting (at the top of the file, just after the imports).

So I tried to configure these lines inside the cb_create function, and package loads.

 

# -*- mode: python; python-indent: 4 -*-

#import debugpy
#debugpy.listen(("172.25.74.27",5678))
#print ("Attente de la connexion du debuger...")
#debugpy.wait_for_client()  # blocks execution until client is attached

import ncs
from ncs.application import Service

# ------------------------
# SERVICE CALLBACK EXAMPLE
# ------------------------
class ServiceCallbacks(Service):

    # The create() callback is invoked inside NCS FASTMAP and
    # must always exiscomment 
    .create
    def cb_create(self, tctx, root, service, proplist):
        self.log.info('Service create(service=', service._path, ')')
        
        import debugpy
        debugpy.listen(("172.25.74.27",5678))
        print ("Attente de la connexion du debuger...")
        debugpy.wait_for_client()  # blocks execution until client is attached


        template = ncs.template.Template(service)
        vars = ncs.template.Variables()
        
        for vlan in service.rfs_vlan:
            breakpoint()
            desc = "NSO " + vlan.rfs_description
            vars.add('DESCRIPTION', desc)
            vars.add('VLAN_ID', vlan.rfs_vlan_id)
            vars.add('IP_ADD', vlan.rfs_ip_add)
            self.log.info(f"vars: {vars}")
            template.apply('rfs-router-intf-template', vars)

# ---------------------------------------------
# COMPONENT THREAD THAT WILL BE STARTED BY NCS.
# ---------------------------------------------
class Main(ncs.application.Application):
    def setup(self):
        self.log.info('Main RUNNING')
        self.register_service('rfs-router-intf', ServiceCallbacks)

    def teardown(self):
        self.log.info('Main FINISHED')

print ("start")
# breakpoint()
print ("stop")

 

When I create the service within NSO, the breakpoint works (not the bullets in vscode), but the debug is not efficient because vscode can't find the py file (an other issue with the path to python file, I guess).

When you do a package reload, NSO copies and untars the packages from the package directory to the state directory, and the python VM reads the python file from the state directory, So you need to add the /python directories under the state directory to your path.

I modified the "localRoot" with the path to state directory in the launch.json file, and it works.

Thanks very much for your help !