Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Duplicate data in stdout and facts starting with RouterOS 7.2 #132

Open
markwell-ch opened this issue Nov 15, 2022 · 26 comments
Open

Duplicate data in stdout and facts starting with RouterOS 7.2 #132

markwell-ch opened this issue Nov 15, 2022 · 26 comments
Labels
bug Something isn't working

Comments

@markwell-ch
Copy link

SUMMARY

Starting with Router OS 7.2 stdout of community.routeros.command contains the output twice. And when running community.routeros.facts against a device with RouterOS 7.2 or newer (tested up to RouterOS 7.6) hostvars[inventory_hostname]['ansible_net_config'] contains the config twice.

ISSUE TYPE
  • Bug Report
COMPONENT NAME

community.routeros.facts
community.routeros.command

ANSIBLE VERSION
ansible [core 2.13.6]
  config file = /home/markus/gits/ansible-speedcom-backbone/ansible.cfg
  configured module search path = ['/home/markus/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /home/markus/gits/ansible-speedcom-backbone/.venv/lib/python3.10/site-packages/ansible
  ansible collection location = /home/markus/gits/ansible-speedcom-backbone/.ansible/collections
  executable location = /home/markus/gits/ansible-speedcom-backbone/.venv/bin/ansible
  python version = 3.10.6 (main, Nov  2 2022, 18:53:38) [GCC 11.3.0]
  jinja version = 3.1.2
  libyaml = True

COLLECTION VERSION
Collection         Version
------------------ -------
community.routeros 2.3.1 
OS / ENVIRONMENT

RouterOS>=7.2

STEPS TO REPRODUCE
    - name: Collect only the config and default facts
      community.routeros.facts:
        gather_subset:
          - "config"

    - name: Save Config Backup
      ansible.builtin.copy:
        content: "{{ hostvars[inventory_hostname]['ansible_net_config'] }}"
        dest: "{{ backup_dir }}/{{ inventory_hostname }}_config.{{ lookup('pipe', 'date +%Y%m%d') }}.txt"
      delegate_to: localhost

    - name: Run command
      community.routeros.command:
        commands: /system/routerboard/print
      register: config

    - name: Save Output to File
      ansible.builtin.copy:
        content: "{{ config.stdout_lines }}"
        dest: "{{ backup_dir }}/{{ inventory_hostname }}_routerboard_print.{{ lookup('pipe', 'date +%Y%m%d') }}.txt"
      delegate_to: localhost
EXPECTED RESULTS

stdout and hostvars[inventory_hostname]['ansible_net_config'] should not contain duplicate data.

ACTUAL RESULTS

stdout and hostvars[inventory_hostname]['ansible_net_config'] contains duplicate data.

@felixfontein felixfontein added the bug Something isn't working label Nov 16, 2022
@felixfontein
Copy link
Collaborator

Reminds me a bit of #62. I unfortunately don't have ROS 7 (I'm still waiting for a ROS 7 device I ordered earlier this year, damn supply chain problems :D ).

You might want to use the API modules instead if possible.

@markwell-ch
Copy link
Author

Thanks for your reply. Yes, the supply chain problems suck. In the meantime you could also run a VM with the Cloud Hosted Router image, see: https://help.mikrotik.com/docs/pages/viewpage.action?pageId=18350234 or even some unofficial docker image that runs RouterOS inside a container: https://hub.docker.com/r/evilfreelancer/docker-routeros

@therfert
Copy link
Contributor

therfert commented Nov 17, 2022

I noticed the same issue earlier and tried to locate where in the code the problem could be, but I haven't been successful so far.

I also noticed that the behavior isn't persistent. It's radnom - mostly it is duplicated, but occasionally it is not.

What's even worse is that the duplicated output is sometime merged into one line and if a more complex script is passed as the command with new line characters in it, the output of the command is randomly mixed together with the terminal prompt and the command itself and all is duplicated.

The only thing I made sure so far is, that the command is not executed twice. It's duplicate output of the one command execution.

@felixfontein
Copy link
Collaborator

I'm not sure anymore where exactly all the parsing magic happens, but I think it was here or in one of the callers: https://github.com/ansible-collections/ansible.netcommon/blob/main/plugins/connection/network_cli.py#L1176

Last time I've tried debugging something like that I used q (https://github.com/zestyping/q) to dump all kind of stuff in the potentially interesting functions to try to figure out what happens.

@markwell-ch
Copy link
Author

For me the duplication does not happen when ssh_type = paramiko instead of ssh_type = sshlib is used. Important is adding this options to the username ansible_user: username+cte1000w1000h. Maybe smaller numbers will also work. See: https://help.mikrotik.com/docs/display/ROS/Command+Line+Interface#CommandLineInterface-LoginOptions

@izzzhoga
Copy link

You might want to use the API modules instead if possible.

Good time of day. Does RouterOS v7 work correctly with the api modules?

@felixfontein
Copy link
Collaborator

I have not heard anything to the contrary.

@dmqgit
Copy link

dmqgit commented Dec 20, 2022

I have exactly the same issue (routeros 7.5 and 7.6). I can also reproduce that the duplicate output just happens with ssh_type = libssh setting, ssh_type = paramiko looks "normal". I hopefully can try the api implementation soon, at the moment my whole setup is based on ssh. Thanks for any help.

@AleksNovak
Copy link

Hi there,
I think I can reproduce that behavior with community.routeros.command. I have that behavior with one or two command.
Target: RouterOS 7.6

    - name: Configure wireguard interface
      community.routeros.command:
        commands:                           
          - /interface/list/print where name=ADM
          - /interface/list/member/print where interface={{ admin_network_config.wireguard_ifName }} and list=ADM
      register: tutu
      tags:                     
        - toto
               
    - debug:                                                                                                                         
        var: tutu                                                                 
      tags: toto

output:

❯ ansible-playbook -i inventory.ini -t toto mikrotik_wg.yml

PLAY [Install certificates] ************************************************************

TASK [Configure wireguard interface] ***************************************************
changed: [toto]

TASK [debug] ***************************************************************************
ok: [pvc.tiersbox.org] => {
    "tutu": {
        "changed": true,
        "failed": false,
        "stdout": [
            "Columns: NAME\n# NAME\n0 ADMColumns: NAME\n# NAME\n0 ADM",
            "/interface/list/member/print where interface=wg-admin and list=AD\n<nt where interface=wg-admin and list=ADM                                      \n<nt where interface=wg-admin and list=ADM\n<nt where interface=wg-admin and list=ADM\n\nColumns: LIST, INTERFACE\n# LIST  INTERFACE\n0 ADM   wg-admin/interface/list/member/print where interface=wg-admin and list=AD\n<nt where interface=wg-admin and list=ADM                                      \n<nt where interface=wg-admin and list=ADM\n<nt where interface=wg-admin and list=ADM\n\nColumns: LIST, INTERFACE\n# LIST  INTERFACE\n0 ADM   wg-admin"
        ],
        "stdout_lines": [
            [
                "Columns: NAME",
                "# NAME",
                "0 ADMColumns: NAME",
                "# NAME",
                "0 ADM"
            ],
            [
                "/interface/list/member/print where interface=wg-admin and list=AD",
                "<nt where interface=wg-admin and list=ADM                                      ",
                "<nt where interface=wg-admin and list=ADM",
                "<nt where interface=wg-admin and list=ADM",
                "",
                "Columns: LIST, INTERFACE",
                "# LIST  INTERFACE",
                "0 ADM   wg-admin/interface/list/member/print where interface=wg-admin and list=AD",
                "<nt where interface=wg-admin and list=ADM                                      ",
                "<nt where interface=wg-admin and list=ADM",
                "<nt where interface=wg-admin and list=ADM",
                "",
                "Columns: LIST, INTERFACE",
                "# LIST  INTERFACE",
                "0 ADM   wg-admin"
            ]
        ]
    }
}

PLAY RECAP *****************************************************************************
toto           : ok=2    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

@o0-o
Copy link

o0-o commented Feb 16, 2023

I unfortunately don't have ROS 7 (I'm still waiting for a ROS 7 device I ordered earlier this year, damn supply chain problems :D ).

You can run ROS 7 for free using Vagrant. The Vagrant box I'm using is cheretbe/routeros7. The doubling issue is occurring there so it should be possible to diagnose it without any additional hardware or cost. Happy to assist if you are unfamiliar with Vagrant.

Vagrantfile:

Vagrant.configure("2") do |config|

  config.vm.define "routeros7" do |routeros|
    routeros.vm.box = "cheretbe/routeros7"
    routeros.vm.hostname = "routeros7.test"
    routeros.vm.network :forwarded_port, guest: 22, host: 2827, id: "ssh"
  end

end
ok: [routeros7.hq.example.com] => {
    "changed": false,
    "invocation": {
        "module_args": {
            "commands": [
                "/put [/system clock get time]"
            ],
            "interval": 1,
            "match": "all",
            "retries": 10,
            "wait_for": null
        }
    },
    "stdout": [
        "00:54:2600:54:26"
    ],
    "stdout_lines": [
        [
            "00:54:2600:54:26"
        ]
    ]
}

@kar0v
Copy link

kar0v commented Feb 27, 2023

On RouterOS 7.6 I can reproduce this with the community.routeros.command module as well:

---
- name: RouterOS test with network_cli connection
  hosts: routers[0]
  gather_facts: false
  tasks:

  - name: Gather statistics
    community.routeros.command:
      commands:
        - "/interface print stats from=wlan1,wlan2"
    register: print_stats

  - name: Show system resources
    debug:
      var: print_stats

  - name: Create log directory if it does not exist
    file:
      path: ./logs
      state: directory
      mode: '0755'

  - local_action: lineinfile line={{ print_stats | to_nice_yaml}} create=true path="./logs/{{ inventory_hostname }}.log"
TASK [Show system resources] ****************************************************************************
ok: [192.168.179.231] => 
  msg:
    ansible_facts:
      discovered_interpreter_python: /usr/bin/python3
    changed: true
    failed: false
    stdout:
    - |-
      Flags: D - dynamic; X - disabled, R - running; S - slave; P - passthrough
       #      NAME              RX-BYTE           TX-BYTE     RX-PACKET     TX-PACKET
       0  RS  ;;; managed by CAPsMAN
              ;;; channel: 2462/20-eC/gn(14dBm), SSID: X_24, local forwarding
              wlan1          46 654 072    12 532 162 795       198 471    24 568 945
       1  RS  ;;; managed by CAPsMAN
              ;;; channel: 5180/20-Ceee/ac(11dBm), SSID: X, local forwarding
              wlan2       1 093 050 444    16 045 504 342     2 364 491    28 825 963Flags: D - dynamic; X - disabled, R - running; S - slave; P - passthrough
       #      NAME              RX-BYTE           TX-BYTE     RX-PACKET     TX-PACKET
       0  RS  ;;; managed by CAPsMAN
              ;;; channel: 2462/20-eC/gn(14dBm), SSID: X_24, local forwarding
              wlan1          46 654 072    12 532 162 795       198 471    24 568 945
       1  RS  ;;; managed by CAPsMAN
              ;;; channel: 5180/20-Ceee/ac(11dBm), SSID: X, local forwarding
              wlan2       1 093 050 444    16 045 504 342     2 364 491    28 825 963
    stdout_lines:
    - - 'Flags: D - dynamic; X - disabled, R - running; S - slave; P - passthrough '
      - ' #      NAME              RX-BYTE           TX-BYTE     RX-PACKET     TX-PACKET'
      - ' 0  RS  ;;; managed by CAPsMAN'
      - '        ;;; channel: 2462/20-eC/gn(14dBm), SSID: X_24, local forwarding'
      - '        wlan1          46 654 072    12 532 162 795       198 471    24 568 945'
      - ' 1  RS  ;;; managed by CAPsMAN'
      - '        ;;; channel: 5180/20-Ceee/ac(11dBm), SSID: X, local forwarding'
      - '        wlan2       1 093 050 444    16 045 504 342     2 364 491    28 825 963Flags: D - dynamic; X - disabled, R - running; S - slave; P - passthrough '
      - ' #      NAME              RX-BYTE           TX-BYTE     RX-PACKET     TX-PACKET'
      - ' 0  RS  ;;; managed by CAPsMAN'
      - '        ;;; channel: 2462/20-eC/gn(14dBm), SSID: X_24, local forwarding'
      - '        wlan1          46 654 072    12 532 162 795       198 471    24 568 945'
      - ' 1  RS  ;;; managed by CAPsMAN'
      - '        ;;; channel: 5180/20-Ceee/ac(11dBm), SSID: X, local forwarding'
      - '        wlan2       1 093 050 444    16 045 504 342     2 364 491    28 825 963'

@o0-o
Copy link

o0-o commented Feb 27, 2023

I am pretty confident that it is an upstream issue. It definitely relates to libssh although I suppose the bug could be in network_cli or elsewhere. I don't have a good understanding of how network modules like this work. It will likely be up to one of the maintainers here to investigate and file the appropriate issue upstream.

I have switched to using paramiko and have had no problems. However, my use of Ansible with Mikrotik devices is minimal so your mileage may vary.

@felixfontein
Copy link
Collaborator

I've finally got my ROS7 device, I'll see whether I can debug this a bit next weekend or so...

@felixfontein
Copy link
Collaborator

I think I managed to figure out what goes wrong; it seems to be a bug in the ansible.netcommon.network_cli connection plugin: ansible-collections/ansible.netcommon#517

When applying that change the duplicate output no longer happens for me.

@Qalthos
Copy link

Qalthos commented Mar 1, 2023

I took a look through everything, and while the fix does work, I don't think ansible-collections/ansible.netcommon#517 is quite the right answer. Can someone test ansible-collections/ansible.netcommon#521 and let me know if that works as well?

@felixfontein
Copy link
Collaborator

@Qalthos I tested ansible-collections/ansible.netcommon#521, it also fixes the problem for me!

@Qalthos
Copy link

Qalthos commented Mar 1, 2023

Cool. Thanks for looking into it. I've closed 517 in favor of 521 and will merge 521 when I get a chance.

@felixfontein
Copy link
Collaborator

@Qalthos cool, thanks a lot! Will it be possible to do a new 4.x.y bugfix release once that is merged?

@Qalthos
Copy link

Qalthos commented Mar 2, 2023

We won't be able to do that, unfortunately.

@izzzhoga
Copy link

izzzhoga commented Mar 9, 2023

I have exactly the same problem with duplicating data, only on RouterOS 7.8

Haven't fixed the bug yet?

@izzzhoga
Copy link

izzzhoga commented Mar 9, 2023

I dare to assume that because of this problem, the collection of facts on RouterOS 7.2-7.8 is broken, the example below.

- name: Collect all facts from the device
  community.routeros.facts:
    gather_subset: all
  register: all_facts

The error I'm getting:

fatal: [mikrotik]: FAILED! => {
    "changed": false,
    "module_stderr": "Traceback (most recent call last):\n  File \"/home/user/.ansible/tmp/ansible-local-3253737c37dt00n/ansible-tmp-1678356214.2582262-3254449-220312769211413/AnsiballZ_facts.py\", line 107, in <module>\n    _ansiballz_main()\n  File \"/home/user/.ansible/tmp/ansible-local-3253737c37dt00n/ansible-tmp-1678356214.2582262-3254449-220312769211413/AnsiballZ_facts.py\", line 99, in _ansiballz_main\n    invoke_module(zipped_mod, temp_path, ANSIBALLZ_PARAMS)\n  File \"/home/user/.ansible/tmp/ansible-local-3253737c37dt00n/ansible-tmp-1678356214.2582262-3254449-220312769211413/AnsiballZ_facts.py\", line 47, in invoke_module\n    runpy.run_module(mod_name='ansible_collections.community.routeros.plugins.modules.facts', init_globals=dict(_module_fqn='ansible_collections.community.routeros.plugins.modules.facts', _modlib_path=modlib_path),\n  File \"/usr/lib/python3.9/runpy.py\", line 210, in run_module\n    return _run_module_code(code, init_globals, run_name, mod_spec)\n  File \"/usr/lib/python3.9/runpy.py\", line 97, in _run_module_code\n    _run_code(code, mod_globals, init_globals,\n  File \"/usr/lib/python3.9/runpy.py\", line 87, in _run_code\n    exec(code, run_globals)\n  File \"/tmp/ansible_community.routeros.facts_payload_n6n95orf/ansible_community.routeros.facts_payload.zip/ansible_collections/community/routeros/plugins/modules/facts.py\", line 663, in <module>\n  File \"/tmp/ansible_community.routeros.facts_payload_n6n95orf/ansible_community.routeros.facts_payload.zip/ansible_collections/community/routeros/plugins/modules/facts.py\", line 651, in main\n  File \"/tmp/ansible_community.routeros.facts_payload_n6n95orf/ansible_community.routeros.facts_payload.zip/ansible_collections/community/routeros/plugins/modules/facts.py\", line 455, in populate\n  File \"/tmp/ansible_community.routeros.facts_payload_n6n95orf/ansible_community.routeros.facts_payload.zip/ansible_collections/community/routeros/plugins/modules/facts.py\", line 532, in parse_route\n  File \"/tmp/ansible_community.routeros.facts_payload_n6n95orf/ansible_community.routeros.facts_payload.zip/ansible_collections/community/routeros/plugins/modules/facts.py\", line 474, in preprocess\nIndexError: list index out of range\n",
    "module_stdout": "",
    "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error",
    "rc": 1
}

Is it necessary to open a new bug report for this?

@felixfontein
Copy link
Collaborator

@izzzhoga while ansible-collections/ansible.netcommon#521 has been merged, no new release of ansible.netcommon has been made. Once a new release is out and you installed that one, the problem should be gone. If you want to have it fixed earlier, you need to patch your local ansible.netcommon install accordingly.

The problem you have with facts gathering could also be caused by this. If the problem still happens with that fix applied, opening a new issue would help (then it's a problem in this collection).

@izzzhoga
Copy link

izzzhoga commented Mar 9, 2023

@felixfontein Please tell me when the new version of the module is planned to be released? :)

@felixfontein
Copy link
Collaborator

@izzzhoga I do not know when the ansible.netcommon collection will have another release.

@felixfontein
Copy link
Collaborator

ansible.netcommon 5.1.0 has been released (https://github.com/ansible-collections/ansible.netcommon/tree/5.1.0), it should contain that fix. (The changelog does mention it: https://github.com/ansible-collections/ansible.netcommon/blob/main/CHANGELOG.rst#v510)

@felixfontein
Copy link
Collaborator

(If you are using Ansible (and not ansible-core with your own set of collections), you will have to wait for Ansible 8.0.0 though since it is a newer major version than the version included in 7.x.y.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants