Juniper Timeout/Error Connecting

[ben-stratagem]

Similar to #162 and #156 - using Hyperglass to query our MX960 for the most part results in a generic error message "Error connecting to $Location: No response."

The ping function works and returns results via Hyperglass but seemingly only for 8.8.8.8 / 8.8.4.4 / 1.1.1.1 (seems to be only short addresses) - any other address or function (traceroute etc) fails with the above error. IPv6 won't return anything. We have dual routing engines and the ping results also include the {master} given on the Junos prompt.

Have tried a slightly older version of Hyperglass but no change. Tried altering the driver to Netmiko and updating the timeout but also no change.

Logs with IP addresses removed:

{"text": "[DEBUG] 20210910 18:00:51 | hyperglass.execution.drivers._construct:36 | __init__ \u2192 Constructing ping query for '$PingDestination'\n", "record": {"elapsed": {"repr": "0:10:49.220314", "seconds": 649.220314}, "exception": null, "extra": {}, "file": {"name": "_construct.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/_construct.py"}, "function": "__init__", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 36, "message": "Constructing ping query for '$PingDestination'", "module": "_construct", "name": "hyperglass.execution.drivers._construct", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.063492+01:00", "timestamp": 1631293251.063492}}}

{"text": "[DEBUG] 20210910 18:00:51 | hyperglass.execution.drivers._construct:160 | queries \u2192 Constructed query: ['ping inet $PingDestination count 5 source $RouterSourceIP']\n", "record": {"elapsed": {"repr": "0:10:49.221055", "seconds": 649.221055}, "exception": null, "extra": {}, "file": {"name": "_construct.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/_construct.py"}, "function": "queries", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 160, "message": "Constructed query: ['ping inet $PingDestination count 5 source $RouterSourceIP']", "module": "_construct", "name": "hyperglass.execution.drivers._construct", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.064233+01:00", "timestamp": 1631293251.064233}}}

{"text": "[DEBUG] 20210910 18:00:51 | hyperglass.execution.drivers.ssh_scrapli:83 | collect \u2192 Connecting directly to Wolverhampton\n", "record": {"elapsed": {"repr": "0:10:49.221885", "seconds": 649.221885}, "exception": null, "extra": {}, "file": {"name": "ssh_scrapli.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/ssh_scrapli.py"}, "function": "collect", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 83, "message": "Connecting directly to Wolverhampton", "module": "ssh_scrapli", "name": "hyperglass.execution.drivers.ssh_scrapli", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.065063+01:00", "timestamp": 1631293251.065063}}}

{"text": "[INFO] 20210910 18:00:51 | scrapli.driver.base.base_driver:930 | _pre_open_closing_log \u2192 opening connection to '$RouterIP' on port '22'\n", "record": {"elapsed": {"repr": "0:10:49.310259", "seconds": 649.310259}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/base/base_driver.py"}, "function": "_pre_open_closing_log", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 930, "message": "opening connection to '$RouterIP' on port '22'", "module": "base_driver", "name": "scrapli.driver.base.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.153437+01:00", "timestamp": 1631293251.153437}}}

{"text": "[INFO] 20210910 18:00:51 | scrapli.driver.network.base_driver:312 | _process_acquire_priv \u2192 attempting to acquire 'exec' privilege level\n", "record": {"elapsed": {"repr": "0:10:49.726736", "seconds": 649.726736}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/network/base_driver.py"}, "function": "_process_acquire_priv", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 312, "message": "attempting to acquire 'exec' privilege level", "module": "base_driver", "name": "scrapli.driver.network.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.569914+01:00", "timestamp": 1631293251.569914}}}

{"text": "[DEBUG] 20210910 18:00:51 | scrapli.driver.network.base_driver:133 | _determine_current_priv \u2192 determined current privilege level is one of '['exec']'\n", "record": {"elapsed": {"repr": "0:10:49.731781", "seconds": 649.731781}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/network/base_driver.py"}, "function": "_determine_current_priv", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 133, "message": "determined current privilege level is one of '['exec']'", "module": "base_driver", "name": "scrapli.driver.network.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.574959+01:00", "timestamp": 1631293251.574959}}}

{"text": "[DEBUG] 20210910 18:00:51 | scrapli.driver.network.base_driver:322 | _process_acquire_priv \u2192 determined current privilege level is target privilege level, no action needed\n", "record": {"elapsed": {"repr": "0:10:49.732509", "seconds": 649.732509}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/network/base_driver.py"}, "function": "_process_acquire_priv", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 322, "message": "determined current privilege level is target privilege level, no action needed", "module": "base_driver", "name": "scrapli.driver.network.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.575687+01:00", "timestamp": 1631293251.575687}}}

{"text": "[INFO] 20210910 18:00:51 | scrapli.driver.base.base_driver:949 | _post_open_closing_log \u2192 connection to '$RouterIP' on port '22' opened successfully\n", "record": {"elapsed": {"repr": "0:10:49.815289", "seconds": 649.815289}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/base/base_driver.py"}, "function": "_post_open_closing_log", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 949, "message": "connection to '$RouterIP' on port '22' opened successfully", "module": "base_driver", "name": "scrapli.driver.base.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:00:51.658467+01:00", "timestamp": 1631293251.658467}}}

{"text": "[INFO] 20210910 18:01:21 | scrapli.driver.base.base_driver:949 | _post_open_closing_log \u2192 connection to '$RouterIP' on port '22' closed successfully\n", "record": {"elapsed": {"repr": "0:11:19.868916", "seconds": 679.868916}, "exception": null, "extra": {"logger_name": "scrapli.$RouterIP:22-driver"}, "file": {"name": "base_driver.py", "path": "/usr/local/lib/python3.6/site-packages/scrapli/driver/base/base_driver.py"}, "function": "_post_open_closing_log", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 949, "message": "connection to '$RouterIP' on port '22' closed successfully", "module": "base_driver", "name": "scrapli.driver.base.base_driver", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:01:21.712094+01:00", "timestamp": 1631293281.712094}}}

{"text": "[ERROR] 20210910 18:01:21 | hyperglass.execution.drivers.ssh_scrapli:146 | collect \u2192 connection not opened, but attempting to call a method that requires an open connection, do you need to call 'open()'?\n", "record": {"elapsed": {"repr": "0:11:19.871031", "seconds": 679.871031}, "exception": null, "extra": {}, "file": {"name": "ssh_scrapli.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/ssh_scrapli.py"}, "function": "collect", "level": {"icon": "\u274c", "name": "ERROR", "no": 40}, "line": 146, "message": "connection not opened, but attempting to call a method that requires an open connection, do you need to call 'open()'?", "module": "ssh_scrapli", "name": "hyperglass.execution.drivers.ssh_scrapli", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:01:21.714209+01:00", "timestamp": 1631293281.714209}}}

{"text": "[CRITICAL] 20210910 18:01:21 | hyperglass.exceptions:40 | __init__ \u2192 [DANGER] Error connecting to Wolverhampton: No response.\n", "record": {"elapsed": {"repr": "0:11:19.872595", "seconds": 679.872595}, "exception": null, "extra": {}, "file": {"name": "exceptions.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/exceptions.py"}, "function": "__init__", "level": {"icon": "\u2620\ufe0f", "name": "CRITICAL", "no": 50}, "line": 40, "message": "[DANGER] Error connecting to Wolverhampton: No response.", "module": "exceptions", "name": "hyperglass.exceptions", "process": {"id": 256280, "name": "MainProcess"}, "thread": {"id": 140644402113408, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:01:21.715773+01:00", "timestamp": 1631293281.715773}}}

Environment

| hyperglass Version | 1.0.4 |
| hyperglass Path | /etc/hyperglass |
| Python Version | 3.6.8 |
| Node Version | 14.17.5 |
| Platform Info | Linux-4.18.0-305.7.1.el8_4.x86_64-x86_64-with-centos-8.4.2105 |
| CPU Info | Intel(R) Xeon(R) CPU E5-2660 v3 @ 2.60GHz |
| Logical Cores | 4 |
| Physical Cores | 4 |
| Processor Speed | 2.599996GHz |
| Total Memory | 3.92 GB |
| Memory Utilization | 27.6% |
| Total Disk Space | 9.44 GB |
| Disk Utilization | 58.7% |

[thatmattlove]

Out of curiosity, if you add structured: false to the device definition, do you have the same issue? I imagine so based no the logs, but just curious.

Also, can you share the logs from changing the driver to Netmiko?

[ben-stratagem]

Hi Matt

The problem does still occur if I updated structured_output to false (structured: false threw an error)

Logs:

{"text": "[DEBUG] 20210910 18:53:40 | hyperglass.execution.drivers._construct:111 | queries \u2192 Constructed query: ['ping inet $PingDestination count 5 source $RouterSourceIP']\n", "record": {"elapsed": {"repr": "0:00:15.153256", "seconds": 15.153256}, "exception": null, "extra": {}, "file": {"name": "_construct.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/_construct.py"}, "function": "queries", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 111, "message": "Constructed query: ['ping inet $PingDestination count 5 source $RouterSourceIP']", "module": "_construct", "name": "hyperglass.execution.drivers._construct", "process": {"id": 257028, "name": "MainProcess"}, "thread": {"id": 140600983063424, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:53:40.247030+01:00", "timestamp": 1631296420.24703}}}
{"text": "[DEBUG] 20210910 18:53:40 | hyperglass.execution.drivers.ssh_netmiko:57 | collect \u2192 Connecting directly to Wolverhampton\n", "record": {"elapsed": {"repr": "0:00:15.154034", "seconds": 15.154034}, "exception": null, "extra": {}, "file": {"name": "ssh_netmiko.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/ssh_netmiko.py"}, "function": "collect", "level": {"icon": "\ud83d\udc1e", "name": "DEBUG", "no": 10}, "line": 57, "message": "Connecting directly to Wolverhampton", "module": "ssh_netmiko", "name": "hyperglass.execution.drivers.ssh_netmiko", "process": {"id": 257028, "name": "MainProcess"}, "thread": {"id": 140600983063424, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:53:40.247808+01:00", "timestamp": 1631296420.247808}}}
{"text": "[ERROR] 20210910 18:54:00 | hyperglass.execution.drivers.ssh_netmiko:108 | collect \u2192 Timed-out reading channel, data not available.\n", "record": {"elapsed": {"repr": "0:00:35.794024", "seconds": 35.794024}, "exception": null, "extra": {}, "file": {"name": "ssh_netmiko.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/execution/drivers/ssh_netmiko.py"}, "function": "collect", "level": {"icon": "\u274c", "name": "ERROR", "no": 40}, "line": 108, "message": "Timed-out reading channel, data not available.", "module": "ssh_netmiko", "name": "hyperglass.execution.drivers.ssh_netmiko", "process": {"id": 257028, "name": "MainProcess"}, "thread": {"id": 140600983063424, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:54:00.887798+01:00", "timestamp": 1631296440.887798}}}
{"text": "[CRITICAL] 20210910 18:54:00 | hyperglass.exceptions:40 | __init__ \u2192 [DANGER] Error connecting to Wolverhampton: Request timed out.\n", "record": {"elapsed": {"repr": "0:00:35.795951", "seconds": 35.795951}, "exception": null, "extra": {}, "file": {"name": "exceptions.py", "path": "/usr/local/lib/python3.6/site-packages/hyperglass/exceptions.py"}, "function": "__init__", "level": {"icon": "\u2620\ufe0f", "name": "CRITICAL", "no": 50}, "line": 40, "message": "[DANGER] Error connecting to Wolverhampton: Request timed out.", "module": "exceptions", "name": "hyperglass.exceptions", "process": {"id": 257028, "name": "MainProcess"}, "thread": {"id": 140600983063424, "name": "MainThread"}, "time": {"repr": "2021-09-10 18:54:00.889725+01:00", "timestamp": 1631296440.889725}}}```

[MorningLightMountain713]

I came here because of this same error. Testing against a dual RE MX10003. Doesn't work for either Scrapli or Netmiko.

[MorningLightMountain713]

Figured out my issue here. (some netmiko logging) I was using a read-only user, Juniper read-only by default does not allow ping or traceroute. Have to add them as allow-commands

[MorningLightMountain713]

This login class works for me, in case anyone else needs it.

    login {
        class lookingglass {
            permissions [ network routing ];
            allow-commands "(set cli .*)|(show route protocol bgp .*)|(ping .*)|(traceroute .*)|(exit)";
            deny-commands "(.*)";
        }
    }
}

[FurPineapple]

Hi @MorningLightMountain713 . What commands are executed under command set "set cli .*"? Thanks so much!

[marcelordeo]

Hello,

I am also having this problem.

I've tried the solution mentioned but it still doesn't do the tracert.

did anyone manage to solve it?

[channelsss]

Hello
I have a same bug with traceroute on IOS XR

[thatmattlove]

Can anyone re-test this with v2 and update the issue with the results?