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

Adapter eats up UDP ports #282

Closed
TheKilroy opened this issue Jun 30, 2023 · 32 comments
Closed

Adapter eats up UDP ports #282

TheKilroy opened this issue Jun 30, 2023 · 32 comments
Assignees
Labels
bug dependencies Pull requests that update a dependency file fixed

Comments

@TheKilroy
Copy link

** Adapter eats UPD ports **
Having a problem on a Raspberry Pi4 that a simple ping command gave the error message "ping: connect: Resource temporarily unavailable"

root@shsrv01:~# ping 192.168.99.1
ping: connect: Resource temporarily unavailable

Tracing the error I used the command

# lsof -i -n | grep snmp

which gave me an endless list of entries like

io.snmp.0 17911 iobroker *092u IPv4 1366517 0t0 UDP *:37626

So I used to the command

# lsof -i -n | grep snmp | wc -l
28237

to count the lines. The result was 28237 open UDP sockets by the io.smp process.

To reproduce I restarted because a simple iob stop snmp.0 did not make it. After a few days I got the same result. After a few days again I tried iob stop and iob start and that worked. But that can not be a solution.

Versions:

  • Adapter version: 2.4.7
  • JS-Controller version: 5.0.5
  • Node version: v18.16.0
  • Operating system:
    $ lsb_release -a
    No LSB modules are available.
    Distributor ID: Debian
    Description: Debian GNU/Linux 11 (bullseye)
    Release: 11
    Codename: bullseye

Here the configuration of the SNMP Adapter
Bildschirmfoto-20230630155431-1920x1026
Bildschirmfoto-20230630155709-1920x1026
Bildschirmfoto-20230630160107-928x757

@mcm1957
Copy link
Member

mcm1957 commented Jun 30, 2023

At the first look I cannot reproduce this. I've 2 instances running at my production system. They use exactly one udb port per configured device. The are running since weeks...

Do you have any relevangt logs (exceptions, errors) which might be related?
Do you use writeable states?

@mcm1957
Copy link
Member

mcm1957 commented Jun 30, 2023

Code Review noticed for internal purpose only:
Session could get lost here:

async function onReaderSessionError(pCTX, pErr) {

@TheKilroy
Copy link
Author

I have two different iobroker installations and both show up the same behavior. I just checked the use of the USP port after the restart in the afternoon when I wrote the error report.
Since now there is only one UDP port per configured device as you mentioned.
I have enabled the "debug logging" on both installations now and will come back when I have any news.

@mcm1957
Copy link
Member

mcm1957 commented Jul 1, 2023

I've asked at forum test thread. Until now I did not get any feedback.

Currently only one code part could cause lost udb port. In this case you should have a warning logged:

````device ${pCTX.name} (${pCTX.ipAddr}) reported error ${pErr.toString}```

Could you please check you logs (including older logs if possible) if you have such warnings logegd from snmp adapter. Each such warning could possibly result in one lost udp port.

@TheKilroy
Copy link
Author

Unfortunately I could not reproduce that problem again. I had it before a few times with having traced it down to the SNMP adapter.
As mentioned before I have 2 Raspberry Pi installations and both had that problem in the past. I have configured the instance as to set it to "debug log" so that I will get the error message in case it will occur.
Looks very strange to me and I feel a bit embarrassed that it could not be reproduced. One the other hand it is good that this problem does not occur anymore.
Lets stay calm for a few days and if it does not occur anymore I will close the issue with the option to re-open it in case it will happen again.

I have also mis-configured one of the installations with an ip that does not exist and an ip without a running snmp daemon just in case it a bad line is the reason for that problem. Backgound: I do have a wireless connection between two buildings and this might have bad connections sometimes.

Regards

@mcm1957
Copy link
Member

mcm1957 commented Jul 2, 2023

Yes i would keep the ossue open any2ay.

Could you please check if older logs exist and scsn for ghe warning i mentioned befote. Maybe an instable line could cause udp errors.

On he other side i do not gave a real idea how to force errors at udp port as its connectionless.

@TheKilroy
Copy link
Author

After I wrote my comment this morning without any new issues I have just ran into the problem now again on both machines.
But the missing UDP ports prevent the generating if a log file print and even to open the iobroker admin page

pi@shsrv02:/opt/iobroker $ iob logs snmp
Uncaught Rejection: Error: Cannot create a string longer than 0xffffff0 characters
at Object.slice (node:buffer:652:37)
at Buffer.toString (node:buffer:871:14)
at CLILogs.execute (/opt/iobroker/node_modules/@iobroker/js-controller-cli/build/lib/cli/cliLogs.js:39:67)
at processCommand (/opt/iobroker/node_modules/@iobroker/js-controller-cli/build/lib/setup.js:1056:25)
at Object.execute (/opt/iobroker/node_modules/@iobroker/js-controller-cli/build/lib/setup.js:3138:5)
at Object. (/opt/iobroker/node_modules/iobroker.js-controller/iobroker.js:1:40)
at Module._compile (node:internal/modules/cjs/loader:1256:14)
at Module._extensions..js (node:internal/modules/cjs/loader:1310:10)
at Module.load (node:internal/modules/cjs/loader:1119:32)
at Module._load (node:internal/modules/cjs/loader:960:12)
pi@shsrv02:/opt/iobroker $

Now I created a log file with all SNMP adapter message which I will attach here. Be aware that the compressed file is only 13MB but the uncompressed file is about 500MB. Maybe that help to track down the problem.

This log file is NOT from the system with the wireless connection. So that seem not to be the problem.

iobroker.current.log.snmp.12.txt.gz

@mcm1957
Copy link
Member

mcm1957 commented Jul 2, 2023

Thanks i ll check the log.
But has to wait for pc, my mobile cannot handle this

@TheKilroy
Copy link
Author

TheKilroy commented Jul 2, 2023

Just take your time. For your information also a screenshot of the top processes. Please note the CPU percentage.

Bildschirmfoto-20230702161840-1336x822

@TheKilroy
Copy link
Author

2023-06-29 15:40:10.252 - warn: snmp.0 (17911) device ShAp01 (192.168.1.91) reported error function toString() { [native code] }

frank@lnx03:~/tmp/iobroker/shsrv01$ cat iobroker.*.log | grep -i snmp | grep -i "reported error"|wc -l
72077
frank@lnx03:~/tmp/iobroker/shsrv01$

Just a short snippet from the log. No other messages between.

2023-06-29 12:33:16.217 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.218 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.219 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.219 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.220 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.221 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.222 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.222 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.223 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.223 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 12:33:16.224 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp00 (192.168.1.90) reported error function toString() { [native code] }
2023-06-29 15:31:41.626 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp01 (192.168.1.91) reported error function toString() { [native code] }
2023-06-29 15:40:10.252 - ESC[33mwarnESC[39m: snmp.0 (17911) device ShAp01 (192.168.1.91) reported error function toString() { [native code] }
2023-06-29 19:21:02.341 - ESC[32minfoESC[39m: snmp.0 (17911) [ShAp01] device disconnected - request timeout

Similar messages on both installations.

@mcm1957
Copy link
Member

mcm1957 commented Jul 2, 2023

Thanks for investigation.
The meassage is from exact the suspect code line. Each of this warning indicates one lost udp port.

And there seems to be a second error there - normally there should be an error text output...
So at the meoment I have no glue why the udp port raises an error at your side.

I'll correct the code and give feedback as soon as it is testable.

@mcm1957 mcm1957 added bug next release planned for next release PRIORITY and removed analyze in progress labels Jul 2, 2023
@mcm1957 mcm1957 added this to the Release 2.4.x fixes milestone Jul 2, 2023
@TheKilroy
Copy link
Author

TheKilroy commented Jul 3, 2023

The SNMP instance polls my network components (access points) regularly. These AP do have the mini_snmpd running. Would you need the config files of them to eventually run a virtual machine?

Some other note: after a while the adapter seems to release all the ports and the same repeats.

mcm1957 added a commit that referenced this issue Jul 4, 2023
* (McM1957) fixed: UDP ports got lost during error handling (#282)
* (McM1957) fixed: Incorrect toString() syntax caused several issues, i.e. missing error output (#283)
* (McM1957) Dependencies have been updated
@mcm1957 mcm1957 added fixed and removed next release planned for next release labels Jul 4, 2023
@mcm1957
Copy link
Member

mcm1957 commented Jul 4, 2023

should be fixed with 2.4.8

@TheKilroy
There were two indipendent error in code:

a) normalle the errortext should be output with the warning filtered by you. Du to atyp this was not the case. Starting with 2.4.8 the error text delivered by node-net-snmp should be visible now. In addition the complete stringified arror objet is output when enebling debug logging. This should enable you (or me?) to solve the original problem causing the errors

b) whenever an error was signalled the udp port was not close but a new one was opended. Thus for every error one udp port got lost. This should be fixed now to - although I hope the errors occure at your system still to verify this.

So please test 2.4.8 id possible at one of your systems. The release is available at github and will be available at latest repository tomorrow. Please be aware that this is a beta/latest release so do not use it at productive systems or take at least special care and ensure that you have a working (and restoreable) backup.

Thanks for any feedback.
McM1957

@TheKilroy
Copy link
Author

Thank you for your effort. I have installed the new version directly from github and will observe it the next time.
I have installed it on one of the two machines, so there should be a difference to see somehow.
I will report what I will observe.
Thanks
Kilroy

@TheKilroy
Copy link
Author

Some new info and and a snipped from the log file. Checked the log file today and the number of used UDP ports. Here a snippet from the system with the 2.4.8 version. Result: no missing ports, but an error message.
On the system with the 2.4.7 version no error yet.

2023-07-05 17:47:25.092 - debug: snmp.0 (14920) session for device "ShBridge" (192.168.99.111) created
2023-07-05 17:47:36.863 - debug: snmp.0 (14920) handleConnectionInfo
2023-07-05 17:47:44.641 - debug: snmp.0 (14920) readOIDs - device "wrt_eg" (192.168.99.1)
2023-07-05 17:47:44.641 - debug: snmp.0 (14920) [wrt_eg] processing oid chunk index 0
2023-07-05 17:47:44.642 - debug: snmp.0 (14920) readChunkOIDs - device "wrt_eg" (192.168.99.1), chunk idx 0
2023-07-05 17:47:44.651 - debug: snmp.0 (14920) [wrt_eg] session.get completed for chunk index 0
2023-07-05 17:47:44.709 - debug: snmp.0 (14920) processVarbind - [wrt_eg] wrt_eg.sysName
2023-07-05 17:47:44.710 - debug: snmp.0 (14920) varbindDeode - decode varbind
2023-07-05 17:47:44.710 - debug: snmp.0 (14920) oidObjType2Text - stringify oid object type
2023-07-05 17:47:44.711 - debug: snmp.0 (14920) [wrt_eg] wrt_eg.sysName (OctetString){"oid":"1.3.6.1.2.1.1.5.0","type":4,"value":{"type":"Buffer","data":[119,114,116,95,101,103,46,107,105,108,114,111,121,46,108,111,99,97,108]}}
2023-07-05 17:47:44.711 - debug: snmp.0 (14920) [wrt_eg] update wrt_eg.sysName: wrt_eg.kilroy.local
2023-07-05 17:47:44.711 - debug: snmp.0 (14920) initobject wrt_eg.sysName
2023-07-05 17:47:44.712 - debug: snmp.0 (14920) processVarbind - [wrt_eg] wrt_eg.sysUptime
2023-07-05 17:47:44.712 - debug: snmp.0 (14920) varbindDeode - decode varbind
2023-07-05 17:47:44.712 - debug: snmp.0 (14920) oidObjType2Text - stringify oid object type
2023-07-05 17:47:44.713 - debug: snmp.0 (14920) [wrt_eg] wrt_eg.sysUptime (TimeTicks){"oid":"1.3.6.1.2.1.1.3.0","type":67,"value":32295186}
2023-07-05 17:47:44.713 - debug: snmp.0 (14920) [wrt_eg] update wrt_eg.sysUptime: 32295186
2023-07-05 17:47:44.713 - debug: snmp.0 (14920) initobject wrt_eg.sysUptime
2023-07-05 17:47:44.713 - debug: snmp.0 (14920) processVarbind - [wrt_eg] wrt_eg.hrSystemUptime
2023-07-05 17:47:44.714 - debug: snmp.0 (14920) varbindDeode - decode varbind
2023-07-05 17:47:44.714 - debug: snmp.0 (14920) oidObjType2Text - stringify oid object type
2023-07-05 17:47:44.714 - debug: snmp.0 (14920) [wrt_eg] wrt_eg.hrSystemUptime (TimeTicks){"oid":"1.3.6.1.2.1.25.1.1.0","type":67,"value":34101217}
2023-07-05 17:47:44.715 - debug: snmp.0 (14920) [wrt_eg] update wrt_eg.hrSystemUptime: 34101217
2023-07-05 17:47:44.715 - debug: snmp.0 (14920) initobject wrt_eg.hrSystemUptime
2023-07-05 17:47:44.715 - debug: snmp.0 (14920) setStates - wrt_eg.sysName
2023-07-05 17:47:44.716 - debug: snmp.0 (14920) setStates - wrt_eg.sysUptime
2023-07-05 17:47:44.716 - debug: snmp.0 (14920) setStates - wrt_eg.hrSystemUptime
2023-07-05 17:47:44.716 - debug: snmp.0 (14920) [wrt_eg] processing oid chunk index 0 completed
2023-07-05 17:47:44.912 - debug: snmp.0 (14920) createReaderSession - device ShBridge (192.168.99.111)
2023-07-05 17:47:44.924 - debug: snmp.0 (14920) snmpCreateSession - device ShBridge (192.168.99.111)
2023-07-05 17:47:44.925 - debug: snmp.0 (14920) session for device "ShBridge" (192.168.99.111) created
2023-07-05 17:47:44.925 - debug: snmp.0 (14920) readOIDs - device "ShBridge" (192.168.99.111)
2023-07-05 17:47:44.925 - debug: snmp.0 (14920) [ShBridge] processing oid chunk index 0
2023-07-05 17:47:44.925 - debug: snmp.0 (14920) readChunkOIDs - device "ShBridge" (192.168.99.111), chunk idx 0
2023-07-05 17:47:44.930 - debug: snmp.0 (14920) onReaderSessionError - device ShBridge (192.168.99.111) - RangeError: Read integer -5108 is outside the unsigned 32-bit range
2023-07-05 17:47:44.931 - warn: snmp.0 (14920) device ShBridge (192.168.99.111) reported error RangeError: Read integer -5108 is outside the unsigned 32-bit range
2023-07-05 17:47:44.931 - debug: snmp.0 (14920) error dump
2023-07-05 17:47:44.932 - debug: snmp.0 (14920) snmpCloseSession - device ShBridge (192.168.99.111
2023-07-05 17:47:44.932 - debug: snmp.0 (14920) onReaderSessionClose - device ShBridge (192.168.99.111)
2023-07-05 17:47:44.933 - debug: snmp.0 (14920) [ShBridge] session.get completed for chunk index 0
2023-07-05 17:47:44.933 - debug: snmp.0 (14920) [ShBridge] session.get: Error: Socket forcibly closed
2023-07-05 17:47:44.934 - debug: snmp.0 (14920) setStates - ShBridge.sysName
2023-07-05 17:47:45.003 - debug: snmp.0 (14920) setStates - ShBridge.sysUptime
2023-07-05 17:47:45.052 - debug: snmp.0 (14920) setStates - ShBridge.hrSystemUptime
2023-07-05 17:47:45.112 - debug: snmp.0 (14920) [ShBridge] processing oid chunk index 0 completed

It seems to be solved but I will observe it for a few days.

The error probably comes from the use of the mini_smpd on my OpenWrt router. As far as I have seen are all values limited to 32bit numbers, but I will double check it.

@mcm1957
Copy link
Member

mcm1957 commented Jul 5, 2023

Ok,
The primary erro is now logged. Theres a problem that node-net-snmp seem to receive data which do not fit into the data type specified. The dump of the error bock is missing - I'll have to check this again. The port / session is now closed as expected after an error.

What I'm missing is a create session afterwards, This should occure after the retry timeout (I think 5 sec per default). Without this createSession no future data would be recorded for this device. Please verify that the device is not dead after an error forever.

By checking use raw states and use type states you should be able to see which data type and which (binary) data is transmitted - but only if the data can be read and passed to the adapter. Mayby this can help diagnosing the oid with problems.

The -5108 could either be an overflow or the type of the oid should be signed int32.

There could be an error at node-net-snmp too, but befor opening a issue there more data would be required.

Thanks for testing.

@mcm1957
Copy link
Member

mcm1957 commented Jul 5, 2023

I've created a new release 2.4.9

-) the extended json stringified dump of the error will now be displyed (at least I hope so :-) )
-) I've added a ne option to disable closing the session in case of an error.

image

I'm not sure if closing the session is really required or node-net-snmp (the layer provising the snmp encoding/decoding) could continue without a reset of the session. With this option both possibilities are available now. So please try disabling closing the session. The main difference will be that an active read block will not be aborted and that no retry wait time is set up.

@TheKilroy
Copy link
Author

Ypu are right, that a new session is created. I just did not copy the lines from the log file.

2023-07-05 17:47:45.112 - ESC[34mdebugESC[39m: snmp.0 (14920) [ShBridge] processing oid chunk index 0 completed
2023-07-05 17:47:45.113 - ESC[34mdebugESC[39m: snmp.0 (14920) session for device "ShBridge" (192.168.99.111) created
2023-07-05 17:47:51.863 - ESC[34mdebugESC[39m: snmp.0 (14920) handleConnectionInfo
2023-07-05 17:48:04.933 - ESC[34mdebugESC[39m: snmp.0 (14920) createReaderSession - device ShBridge (192.168.99.111)
2023-07-05 17:48:04.951 - ESC[34mdebugESC[39m: snmp.0 (14920) snmpCreateSession - device ShBridge (192.168.99.111)
2023-07-05 17:48:04.953 - ESC[34mdebugESC[39m: snmp.0 (14920) session for device "ShBridge" (192.168.99.111) created

I have checked both options and will observe the behavior and tomorrow I will install 2.4.9.

Great job done.

@TheKilroy
Copy link
Author

Ports will be closed already with 2.4.8.
Version 2.4.9 also works without any problems so far. I will install it also on the 2nd machine which had the majority of error messages. So I will come back later when I have more information about the kind of the error

@mcm1957
Copy link
Member

mcm1957 commented Jul 7, 2023

Thanks for the update

@TheKilroy
Copy link
Author

Here finally some info about the logging output of version 2.4.9

2023-07-08 14:48:13.902  - debug: snmp.0 (28213) session for device "ShBridge" (192.168.99.111) created
2023-07-08 14:48:13.902  - debug: snmp.0 (28213) readOIDs - device "ShBridge" (192.168.99.111)
2023-07-08 14:48:13.902  - debug: snmp.0 (28213) [ShBridge] processing oid chunk index 0
2023-07-08 14:48:13.903  - debug: snmp.0 (28213) readChunkOIDs - device "ShBridge" (192.168.99.111), chunk idx 0
2023-07-08 14:48:13.912  - debug: snmp.0 (28213) onReaderSessionError - device ShBridge (192.168.99.111) - RangeError: Read integer -6870200 is outside the unsigned 32-bit range
2023-07-08 14:48:13.913  - warn: snmp.0 (28213) device ShBridge (192.168.99.111) reported error RangeError: Read integer -6870200 is outside the unsigned 32-bit range
2023-07-08 14:48:13.913  - debug: snmp.0 (28213) error dump: {JSON.stringify(pErr)}
2023-07-08 14:48:13.913  - debug: snmp.0 (28213) snmpCloseSession - device ShBridge (192.168.99.111
2023-07-08 14:48:13.914  - debug: snmp.0 (28213) onReaderSessionClose - device ShBridge (192.168.99.111)
2023-07-08 14:48:13.915  - debug: snmp.0 (28213) [ShBridge] session.get completed for chunk index 0
2023-07-08 14:48:13.915  - debug: snmp.0 (28213) [ShBridge] session.get: Error: Socket forcibly closed
2023-07-08 14:48:13.915  - debug: snmp.0 (28213) setStates - ShBridge.sysName
2023-07-08 14:48:13.991  - debug: snmp.0 (28213) setStates - ShBridge.sysUptime
2023-07-08 14:48:14.052  - debug: snmp.0 (28213) setStates - ShBridge.hrSystemUptime
2023-07-08 14:48:14.120  - debug: snmp.0 (28213) [ShBridge] processing oid chunk index 0 completed
2023-07-08 14:48:14.120  - debug: snmp.0 (28213) session for device "ShBridge" (192.168.99.111) created

That is the part of the log file showing the error output. Still the range check error about the "unsigned 32bit integer" which is fairly easy to understand that a negative number does not work with it.

I will also attach the a file holding some more lines. These are all lines logged by the SNMP adapter from 14:00 until I copied the file - so about 45 minutes continues log.

For your explanation:
rt01 - is an OpenWrt router with OpenWrt 22.03.5 r20134 and mini_smpd
shbridge - is an OpenWrt router with OpenWrt Backfire 10.03.1
dummy1 - is an ip address with no connected device
dummy2 - is an ip address with a connected device but there is no snmp service running

Thank your for all your effort. I really appreciate your work.

snmp.snip.3.log

@mcm1957
Copy link
Member

mcm1957 commented Jul 8, 2023

Thanks for the feedback.
I've created a 2.4.10 after trying to correct the error output again. I hope the json stringified text is now output. (Sorry fpr the multipel attempts, as I have no glue how to cause an error during oid reading I cannot test the code here.).

So 2.4.10 should no longer display
'2023-07-08 14:48:13.913 - debug: snmp.0 (28213) error dump: {JSON.stringify(pErr)}'
but display the content of the error block instead of {JSOIN.stringify(pErr)}

@TheKilroy
Copy link
Author

I will test it and will report

@TheKilroy
Copy link
Author

TheKilroy commented Jul 9, 2023

Here is the latest output to the log file showing the error message

2023-07-09 09:52:30.814  - debug: snmp.0 (19952) createReaderSession - device ShBridge (192.168.99.111)
2023-07-09 09:52:30.830  - debug: snmp.0 (19952) snmpCreateSession - device ShBridge (192.168.99.111)
2023-07-09 09:52:30.831  - debug: snmp.0 (19952) session for device "ShBridge" (192.168.99.111) created
2023-07-09 09:52:30.831  - debug: snmp.0 (19952) readOIDs - device "ShBridge" (192.168.99.111)
2023-07-09 09:52:30.832  - debug: snmp.0 (19952) [ShBridge] processing oid chunk index 0
2023-07-09 09:52:30.832  - debug: snmp.0 (19952) readChunkOIDs - device "ShBridge" (192.168.99.111), chunk idx 0
2023-07-09 09:52:30.837  - debug: snmp.0 (19952) onReaderSessionError - device ShBridge (192.168.99.111) - RangeError: Read integer -4304 is outside the unsigned 32-bit range
2023-07-09 09:52:30.837  - warn: snmp.0 (19952) device ShBridge (192.168.99.111) reported error RangeError: Read integer -4304 is outside the unsigned 32-bit range
2023-07-09 09:52:30.838  - debug: snmp.0 (19952) error dump: {}
2023-07-09 09:52:30.838  - debug: snmp.0 (19952) snmpCloseSession - device ShBridge (192.168.99.111
2023-07-09 09:52:30.839  - debug: snmp.0 (19952) onReaderSessionClose - device ShBridge (192.168.99.111)
2023-07-09 09:52:30.839  - debug: snmp.0 (19952) [ShBridge] session.get completed for chunk index 0
2023-07-09 09:52:30.840  - debug: snmp.0 (19952) [ShBridge] session.get: Error: Socket forcibly closed
2023-07-09 09:52:30.840  - debug: snmp.0 (19952) setStates - ShBridge.sysName
2023-07-09 09:52:30.875  - debug: snmp.0 (19952) handleConnectionInfo
2023-07-09 09:52:30.935  - debug: snmp.0 (19952) setStates - ShBridge.sysUptime
2023-07-09 09:52:30.991  - debug: snmp.0 (19952) setStates - ShBridge.hrSystemUptime
2023-07-09 09:52:31.065  - debug: snmp.0 (19952) [ShBridge] processing oid chunk index 0 completed
2023-07-09 09:52:31.066  - debug: snmp.0 (19952) session for device "ShBridge" (192.168.99.111) created

I will attach also a bigger part of the log file where the error message disappears after the value turns positive again. That behavior makes me curious to investigate and I will try to figure out what might be the reason for it.

Thanks and greetings to Austria

snmp.snip.5.log

@mcm1957
Copy link
Member

mcm1957 commented Jul 9, 2023

Thanks for Info.
Unfortunatly the error data seesm to be a simple string only and does not contain additional data.

BUT
I think I found a related issue and PR at the snmp base module:
markabrahams/node-net-snmp#235

As a PR exists I would expect an improved release within a few months.

The reason could be (and this would be fixed by the PR) that you snmp client sends incorrect data. A big unit32 number seems to need a leading zero byte (if the MSB of the real data is set) otherwiese ist is assumed to be negative.

So I see the following real solutions:

-) you cantact the development of your snmp cleint and ask them to check / fix the issue
-) you wait for a ne release of node-net-snmp
-) you manage to keep the affected oids at a lower numreic level, i.e. by restting some counters etc.

I do not see any change to work around the problem at ioBroker.snmp adapter.

@TheKilroy
Copy link
Author

Well, the first issue loosing the UDP ports is solved.
I will wait for the mentioned pull request to be merged and close that issue now.
Thank you.

@mcm1957 mcm1957 reopened this Jul 12, 2023
@mcm1957
Copy link
Member

mcm1957 commented Jul 12, 2023

As a new version of node-net-snmp is on the way I'll keep this open to track implementing ist at iobroker.snmp adapter soon.

@mcm1957 mcm1957 added dependencies Pull requests that update a dependency file and removed PRIORITY labels Jul 12, 2023
mcm1957 added a commit that referenced this issue Jul 13, 2023
* (McM1957) Node-net-snmp has been updated to improve uint32 handling (#282)
* (McM1957) Several other dependencies have been updated
@mcm1957
Copy link
Member

mcm1957 commented Jul 13, 2023

@TheKilroy
I've just released v2.4.11 which included a new version of net-node-snmp. According to releasenotes this new version has a change adding more tolarance for incorrect uint32 data.

Feel free to test the new release and let me know if the problem is fixed completly if you have time for a test. Adapter version 2.4.11 will be available at latest repo tomorrow.

@TheKilroy
Copy link
Author

Thank you. Will install it right away now and let you know.

@mcm1957
Copy link
Member

mcm1957 commented Jul 17, 2023

@TheKilroy
Sorry to distzurb
Did you have time to update the adapter in the meantime?
Is the original error fixed now (or better didi it no longer occure)?

@TheKilroy
Copy link
Author

Sorry for the late reply.I have updated both installations and all seems to be fixed. No error anymore - not the original one and not the resulting. So you may close it from my point of view.
Big thank you.

@mcm1957
Copy link
Member

mcm1957 commented Jul 20, 2023

Fixed with 2.4.11

@mcm1957 mcm1957 closed this as completed Jul 20, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug dependencies Pull requests that update a dependency file fixed
Projects
None yet
Development

No branches or pull requests

2 participants