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

ppp-2.5.0 Sent Bytes Counter Seems to Be Over-reporting #443

Open
gerickson opened this issue Aug 31, 2023 · 10 comments
Open

ppp-2.5.0 Sent Bytes Counter Seems to Be Over-reporting #443

gerickson opened this issue Aug 31, 2023 · 10 comments
Assignees

Comments

@gerickson
Copy link

I recently updated from ppp-2.4.7 to ppp-2.5.0 and have noted for another otherwise-fixed connect-transmit-disconnect sequence that ppp-2.5.0 seems to be dramatically over-reporting the number of sent bytes.

This log stream is demonstrative:

###
### Running on ppp-2.4.7 here:
###

2023-08-21T04:30:26Z: 19205455: daemon.info pppd[12606]: Sent 31981 bytes, received 20722 bytes.
2023-08-21T05:20:03Z: 19205455: daemon.info pppd[13186]: Sent 18516 bytes, received 12944 bytes.
2023-08-21T15:23:22Z: 19205455: daemon.info pppd[13186]: Sent 234664 bytes, received 124804 bytes.
2023-08-21T18:09:28Z: 19205455: daemon.info pppd[17396]: Sent 69909 bytes, received 35454 bytes.
2023-08-21T19:06:12Z: 19205455: daemon.info pppd[17396]: Sent 17772 bytes, received 11668 bytes.
2023-08-21T19:15:36Z: 19205455: daemon.info pppd[19037]: Sent 832 bytes, received 572 bytes.
2023-08-21T20:26:33Z: 19205455: daemon.info pppd[19037]: Sent 38159 bytes, received 22180 bytes.
2023-08-21T22:03:07Z: 19205455: daemon.info pppd[19713]: Sent 36625 bytes, received 22427 bytes.
2023-08-22T16:32:48Z: 19205455: daemon.info pppd[616]: Sent 12941 bytes, received 12363 bytes.

###
### Update from ppp-2.4.7 to ppp-2.5.0 happens here:
###

2023-08-22T16:41:28Z: 19205455: daemon.info pppd[626]: Sent 4756988 bytes, received 5427 bytes.
2023-08-22T16:49:05Z: 19205455: daemon.info pppd[855]: Sent 5076476 bytes, received 1998 bytes.
2023-08-22T17:55:46Z: 19205455: daemon.info pppd[966]: Sent 5273084 bytes, received 108 bytes.
2023-08-22T18:03:02Z: 19205455: daemon.info pppd[1039]: Sent 5023228 bytes, received 394 bytes.
2023-08-22T18:13:20Z: 19205455: daemon.info pppd[1154]: Sent 4699644 bytes, received 646 bytes.
2023-08-22T23:03:01Z: 19205455: daemon.info pppd[1487]: Sent 4888060 bytes, received 1790 bytes.
2023-08-23T00:12:16Z: 19205455: daemon.info pppd[1713]: Sent 5174780 bytes, received 802 bytes.
2023-08-23T00:21:38Z: 19205455: daemon.info pppd[1864]: Sent 4597244 bytes, received 843 bytes.
2023-08-23T01:04:08Z: 19205455: daemon.info pppd[2052]: Sent 5092860 bytes, received 1678 bytes.
2023-08-23T03:17:37Z: 19205455: daemon.info pppd[2208]: Sent 5125628 bytes, received 551 bytes.
2023-08-23T06:17:14Z: 19205455: daemon.info pppd[2336]: Sent 4867580 bytes, received 1835 bytes.
2023-08-23T07:05:11Z: 19205455: daemon.info pppd[2437]: Sent 4498940 bytes, received 2650 bytes.
2023-08-23T08:13:47Z: 19205455: daemon.info pppd[2621]: Sent 5281276 bytes, received 1843 bytes.
2023-08-23T08:23:48Z: 19205455: daemon.info pppd[2750]: Sent 4859388 bytes, received 1415 bytes.
2023-08-23T09:03:17Z: 19205455: daemon.info pppd[2917]: Sent 4957692 bytes, received 334 bytes.
2023-08-23T09:18:43Z: 19205455: daemon.info pppd[3038]: Sent 5236220 bytes, received 958 bytes.
2023-08-23T09:28:50Z: 19205455: daemon.info pppd[3211]: Sent 4552188 bytes, received 290 bytes.
2023-08-23T09:57:31Z: 19205455: daemon.info pppd[3419]: Sent 4769276 bytes, received 3662 bytes.
2023-08-23T10:04:41Z: 19205455: daemon.info pppd[3529]: Sent 5346812 bytes, received 230 bytes.
2023-08-23T10:13:25Z: 19205455: daemon.info pppd[3624]: Sent 5502460 bytes, received 290 bytes.
2023-08-23T10:25:40Z: 19205455: daemon.info pppd[3773]: Sent 5088764 bytes, received 1720 bytes.
2023-08-23T10:29:55Z: 19205455: daemon.info pppd[3894]: Sent 5191164 bytes, received 394 bytes.
2023-08-23T10:33:32Z: 19205455: daemon.info pppd[3997]: Sent 5170684 bytes, received 687 bytes.
2023-08-23T10:40:22Z: 19205455: daemon.info pppd[4133]: Sent 5248508 bytes, received 1270 bytes.
2023-08-23T10:53:00Z: 19205455: daemon.info pppd[4235]: Sent 5043708 bytes, received 3194 bytes.
2023-08-23T10:58:19Z: 19205455: daemon.info pppd[4435]: Sent 4744700 bytes, received 1616 bytes.
2023-08-23T11:07:38Z: 19205455: daemon.info pppd[4553]: Sent 5064188 bytes, received 154 bytes.
2023-08-23T11:17:12Z: 19205455: daemon.info pppd[4693]: Sent 4621820 bytes, received 1215 bytes.
2023-08-23T11:34:33Z: 19205455: daemon.info pppd[4861]: Sent 5240316 bytes, received 646 bytes.
2023-08-23T11:51:02Z: 19205455: daemon.info pppd[5045]: Sent 5211644 bytes, received 2310 bytes.
2023-08-23T12:14:07Z: 19205455: daemon.info pppd[5195]: Sent 5420540 bytes, received 342 bytes.
2023-08-23T12:46:22Z: 19205455: daemon.info pppd[5369]: Sent 5101052 bytes, received 1480 bytes.
2023-08-23T13:05:38Z: 19205455: daemon.info pppd[5479]: Sent 5248508 bytes, received 3113 bytes.
2023-08-23T13:15:36Z: 19205455: daemon.info pppd[5660]: Sent 4904444 bytes, received 386 bytes.
2023-08-23T13:21:49Z: 19205455: daemon.info pppd[5793]: Sent 5142012 bytes, received 1668 bytes.
2023-08-23T14:16:32Z: 19205455: daemon.info pppd[5945]: Sent 4888060 bytes, received 1207 bytes.
2023-08-23T14:55:58Z: 19205455: daemon.info pppd[6064]: Sent 4548092 bytes, received 5586 bytes.
2023-08-23T15:10:24Z: 19205455: daemon.info pppd[6339]: Sent 5387772 bytes, received 2728 bytes.
2023-08-23T15:32:58Z: 19205455: daemon.info pppd[6427]: Sent 5486076 bytes, received 2022 bytes.
2023-08-23T16:08:35Z: 19205455: daemon.info pppd[6643]: Sent 4929020 bytes, received 438 bytes.
2023-08-23T16:15:20Z: 19205455: daemon.info pppd[6797]: Sent 4773372 bytes, received 174 bytes.
2023-08-23T16:40:25Z: 19205455: daemon.info pppd[6924]: Sent 5260796 bytes, received 5166 bytes.
2023-08-24T00:53:06Z: 19205455: daemon.info pppd[7403]: Sent 4814332 bytes, received 2027 bytes.
2023-08-24T00:56:49Z: 19205455: daemon.info pppd[7501]: Sent 4605436 bytes, received 2310 bytes.
2023-08-24T01:12:02Z: 19205455: daemon.info pppd[7645]: Sent 4838908 bytes, received 1544 bytes.
2023-08-24T01:16:02Z: 19205455: daemon.info pppd[7766]: Sent 5146108 bytes, received 799 bytes.
2023-08-24T06:23:39Z: 19205455: daemon.info pppd[7974]: Sent 5281276 bytes, received 1358 bytes.
2023-08-24T16:35:19Z: 19205455: daemon.info pppd[8168]: Sent 4892156 bytes, received 799 bytes.
2023-08-24T18:08:02Z: 19205455: daemon.info pppd[8313]: Sent 4736508 bytes, received 551 bytes.
2023-08-24T18:42:10Z: 19205455: daemon.info pppd[8400]: Sent 5146108 bytes, received 230 bytes.
2023-08-25T08:53:13Z: 19205455: daemon.info pppd[8712]: Sent 4519420 bytes, received 230 bytes.
2023-08-25T16:45:04Z: 19205455: daemon.info pppd[8917]: Sent 5514748 bytes, received 3086 bytes.
2023-08-25T16:50:33Z: 19205455: daemon.info pppd[9031]: Sent 4806140 bytes, received 146 bytes.
2023-08-25T16:53:47Z: 19205455: daemon.info pppd[9103]: Sent 5039612 bytes, received 168 bytes.
2023-08-25T17:03:58Z: 19205455: daemon.info pppd[9244]: Sent 5522940 bytes, received 334 bytes.
2023-08-25T17:41:06Z: 19205455: daemon.info pppd[9380]: Sent 5502460 bytes, received 5898 bytes.
2023-08-25T18:02:22Z: 19205455: daemon.info pppd[9642]: Sent 4769276 bytes, received 3332 bytes.
2023-08-25T18:09:47Z: 19205455: daemon.info pppd[9797]: Sent 4552188 bytes, received 334 bytes.
2023-08-25T18:53:16Z: 19205455: daemon.info pppd[10033]: Sent 5408252 bytes, received 1478 bytes.
2023-08-25T18:57:26Z: 19205455: daemon.info pppd[10171]: Sent 5244412 bytes, received 438 bytes.
2023-08-25T19:10:31Z: 19205455: daemon.info pppd[10486]: Sent 5125628 bytes, received 542 bytes.
2023-08-25T19:44:59Z: 19205455: daemon.info pppd[11037]: Sent 4802044 bytes, received 168 bytes.
2023-08-25T21:59:26Z: 19205455: daemon.info pppd[11201]: Sent 4609532 bytes, received 438 bytes.
2023-08-25T22:56:06Z: 19205455: daemon.info pppd[11312]: Sent 5146108 bytes, received 1467 bytes.
2023-08-26T00:53:04Z: 19205455: daemon.info pppd[11536]: Sent 5043708 bytes, received 958 bytes.
2023-08-26T01:46:13Z: 19205455: daemon.info pppd[11649]: Sent 4736508 bytes, received 1492 bytes.
2023-08-26T13:42:25Z: 19205455: daemon.info pppd[11914]: Sent 5129724 bytes, received 132 bytes.
2023-08-26T15:42:41Z: 19205455: daemon.info pppd[12096]: Sent 5133820 bytes, received 146 bytes.
2023-08-26T16:55:00Z: 19205455: daemon.info pppd[12356]: Sent 5285372 bytes, received 506 bytes.
2023-08-26T18:48:05Z: 19205455: daemon.info pppd[12511]: Sent 5076476 bytes, received 146 bytes.
2023-08-27T04:05:02Z: 19205455: daemon.info pppd[12964]: Sent 5109244 bytes, received 27710 bytes.
2023-08-27T14:27:56Z: 19205455: daemon.info pppd[620]: Sent 4531708 bytes, received 191846 bytes.
2023-08-27T15:52:48Z: 19205455: daemon.info pppd[3610]: Sent 4834812 bytes, received 15247 bytes.
2023-08-27T16:10:41Z: 19205455: daemon.info pppd[3843]: Sent 5371388 bytes, received 1114 bytes.
2023-08-27T16:47:16Z: 19205455: daemon.info pppd[3946]: Sent 4888060 bytes, received 5274 bytes.
2023-08-27T16:52:09Z: 19205455: daemon.info pppd[4077]: Sent 4916732 bytes, received 2734 bytes.
2023-08-27T19:04:33Z: 19205455: daemon.info pppd[4183]: Sent 4834812 bytes, received 18534 bytes.
2023-08-27T19:42:10Z: 19205455: daemon.info pppd[4374]: Sent 5346812 bytes, received 3514 bytes.
2023-08-27T19:58:52Z: 19205455: daemon.info pppd[4511]: Sent 5268988 bytes, received 1070 bytes.
2023-08-27T21:30:46Z: 19205455: daemon.info pppd[4647]: Sent 4531708 bytes, received 30380 bytes.
2023-08-27T21:52:51Z: 19205455: daemon.info pppd[5006]: Sent 4982268 bytes, received 2024 bytes.
2023-08-27T21:57:12Z: 19205455: daemon.info pppd[5146]: Sent 5342716 bytes, received 2047 bytes.
2023-08-27T22:20:01Z: 19205455: daemon.info pppd[5248]: Sent 5346812 bytes, received 3148 bytes.
2023-08-27T23:19:51Z: 19205455: daemon.info pppd[5354]: Sent 4658684 bytes, received 8266 bytes.
2023-08-27T23:36:22Z: 19205455: daemon.info pppd[5488]: Sent 4642300 bytes, received 2088 bytes.
2023-08-28T00:11:09Z: 19205455: daemon.info pppd[5644]: Sent 4494844 bytes, received 4390 bytes.
2023-08-28T00:29:32Z: 19205455: daemon.info pppd[5811]: Sent 4904444 bytes, received 2780 bytes.
2023-08-28T01:32:57Z: 19205455: daemon.info pppd[5935]: Sent 5129724 bytes, received 17643 bytes.
2023-08-28T02:05:11Z: 19205455: daemon.info pppd[6084]: Sent 4900348 bytes, received 4910 bytes.
2023-08-28T02:51:34Z: 19205455: daemon.info pppd[6215]: Sent 4552188 bytes, received 3588 bytes.
2023-08-28T03:21:55Z: 19205455: daemon.info pppd[6285]: Sent 5445116 bytes, received 4754 bytes.
2023-08-28T03:39:05Z: 19205455: daemon.info pppd[6352]: Sent 5281276 bytes, received 2622 bytes.
2023-08-28T04:06:27Z: 19205455: daemon.info pppd[6423]: Sent 5035516 bytes, received 4182 bytes.
2023-08-28T16:41:12Z: 19205455: daemon.info pppd[613]: Sent 5051900 bytes, received 148839 bytes.
2023-08-28T16:54:22Z: 19205455: daemon.info pppd[3259]: Sent 5445116 bytes, received 438 bytes.
2023-08-28T20:34:22Z: 19205455: daemon.info pppd[3460]: Sent 5211644 bytes, received 17232 bytes.
2023-08-28T20:49:59Z: 19205455: daemon.info pppd[3614]: Sent 5502460 bytes, received 1582 bytes.
2023-08-28T22:59:46Z: 19205455: daemon.info pppd[3758]: Sent 4769276 bytes, received 20543 bytes.
2023-08-28T23:38:18Z: 19205455: daemon.info pppd[4078]: Sent 5240316 bytes, received 1059 bytes.
2023-08-29T02:18:26Z: 19205455: daemon.info pppd[4259]: Sent 4883964 bytes, received 20650 bytes.
2023-08-29T02:25:01Z: 19205455: daemon.info pppd[4586]: Sent 5133820 bytes, received 791 bytes.
2023-08-29T03:09:44Z: 19205455: daemon.info pppd[4707]: Sent 4953596 bytes, received 18430 bytes.
2023-08-29T05:21:45Z: 19205455: daemon.info pppd[4815]: Sent 4867580 bytes, received 17762 bytes.
2023-08-29T05:36:13Z: 19205455: daemon.info pppd[5089]: Sent 5408252 bytes, received 854 bytes.
2023-08-29T05:39:06Z: 19205455: daemon.info pppd[5233]: Sent 4851196 bytes, received 2033 bytes.
2023-08-29T05:56:12Z: 19205455: daemon.info pppd[5366]: Sent 5236220 bytes, received 750 bytes.
2023-08-29T05:59:56Z: 19205455: daemon.info pppd[5474]: Sent 5502460 bytes, received 1833 bytes.
2023-08-29T07:07:27Z: 19205455: daemon.info pppd[5584]: Sent 4556284 bytes, received 663 bytes.
2023-08-29T09:49:02Z: 19205455: daemon.info pppd[5805]: Sent 4883964 bytes, received 1634 bytes.
2023-08-29T09:59:31Z: 19205455: daemon.info pppd[6083]: Sent 5080572 bytes, received 230 bytes.
2023-08-29T11:33:46Z: 19205455: daemon.info pppd[6257]: Sent 5228028 bytes, received 94 bytes.
2023-08-29T12:59:13Z: 19205455: daemon.info pppd[6441]: Sent 5256700 bytes, received 94 bytes.
2023-08-29T14:02:05Z: 19205455: daemon.info pppd[6601]: Sent 4859388 bytes, received 136 bytes.
2023-08-29T14:09:42Z: 19205455: daemon.info pppd[6757]: Sent 5150204 bytes, received 2015 bytes.
2023-08-29T14:27:16Z: 19205455: daemon.info pppd[6843]: Sent 4859388 bytes, received 646 bytes.
2023-08-29T14:31:23Z: 19205455: daemon.info pppd[6993]: Sent 4879868 bytes, received 282 bytes.
2023-08-29T15:52:18Z: 19205455: daemon.info pppd[7122]: Sent 5027324 bytes, received 11046 bytes.
2023-08-29T16:31:30Z: 19205455: daemon.info pppd[7356]: Sent 4478460 bytes, received 2298 bytes.
2023-08-29T16:50:29Z: 19205455: daemon.info pppd[7469]: Sent 5101052 bytes, received 2401 bytes.
2023-08-29T18:07:04Z: 19205455: daemon.info pppd[7746]: Sent 4666876 bytes, received 13332 bytes.
2023-08-29T19:03:31Z: 19205455: daemon.info pppd[8703]: Sent 4535804 bytes, received 677 bytes.
2023-08-29T19:52:39Z: 19205455: daemon.info pppd[8830]: Sent 4556284 bytes, received 18000 bytes.
2023-08-29T19:59:44Z: 19205455: daemon.info pppd[9006]: Sent 4564476 bytes, received 1766 bytes.
2023-08-29T20:09:31Z: 19205455: daemon.info pppd[9111]: Sent 5322236 bytes, received 1326 bytes.
2023-08-29T20:24:37Z: 19205455: daemon.info pppd[9181]: Sent 4646396 bytes, received 2136 bytes.
2023-08-29T21:35:03Z: 19205455: daemon.info pppd[9252]: Sent 4982268 bytes, received 10764 bytes.
2023-08-29T22:02:22Z: 19205455: daemon.info pppd[9402]: Sent 4494844 bytes, received 3662 bytes.
2023-08-29T22:47:45Z: 19205455: daemon.info pppd[9617]: Sent 5322236 bytes, received 5326 bytes.
2023-08-30T00:52:18Z: 19205455: daemon.info pppd[9766]: Sent 4507132 bytes, received 16922 bytes.
2023-08-30T00:59:05Z: 19205455: daemon.info pppd[9957]: Sent 4552188 bytes, received 2264 bytes.
2023-08-30T01:11:58Z: 19205455: daemon.info pppd[10140]: Sent 4982268 bytes, received 698 bytes.
2023-08-30T01:50:50Z: 19205455: daemon.info pppd[10347]: Sent 5285372 bytes, received 2732 bytes.
2023-08-30T03:17:37Z: 19205455: daemon.info pppd[10529]: Sent 4670972 bytes, received 1738 bytes.
2023-08-30T09:22:23Z: 19205455: daemon.info pppd[11066]: Sent 5502460 bytes, received 230 bytes.
2023-08-30T10:59:44Z: 19205455: daemon.info pppd[11198]: Sent 5002748 bytes, received 11202 bytes.
2023-08-30T11:34:21Z: 19205455: daemon.info pppd[11347]: Sent 4724220 bytes, received 551 bytes.
2023-08-30T11:46:32Z: 19205455: daemon.info pppd[11441]: Sent 4838908 bytes, received 154 bytes.
2023-08-30T12:05:26Z: 19205455: daemon.info pppd[11631]: Sent 5240316 bytes, received 230 bytes.
2023-08-30T12:34:23Z: 19205455: daemon.info pppd[11854]: Sent 5240316 bytes, received 230 bytes.
2023-08-30T16:45:32Z: 19205455: daemon.info pppd[12021]: Sent 4736508 bytes, received 30847 bytes.
2023-08-31T03:05:22Z: 19205455: daemon.info pppd[747]: Sent 5019132 bytes, received 52 bytes.
2023-08-31T13:24:40Z: 19205455: daemon.info pppd[929]: Sent 4851196 bytes, received 1544 bytes.
2023-08-31T13:59:36Z: 19205455: daemon.info pppd[1005]: Sent 4527612 bytes, received 1558 bytes.
2023-08-31T16:53:57Z: 19205455: daemon.info pppd[1136]: Sent 4691452 bytes, received 168 bytes.
@Neustradamus
Copy link
Member

@paulusmack, @enaess: Have you seen this ticket?

@paulusmack
Copy link
Collaborator

Interesting. I tried here with a couple of Linux machines connected via serial ports, and the number of bytes sent is reasonable. What is the nature of the underlying connection you're using - is it serial, PPPoE, or what? And did you change kernel version at the same time as you updated ppp? What OS is pppd running on?

If you can find an easy way that I can replicate the problem, that would be useful.

@jkroonza
Copy link
Contributor

@gerickson , could you compare that with the figures as reported using for example "ip -s a" please? I did work to incorporate 64-bit counters and wondering if this possibly relates.

Then please attach strace to the running process to determine how network statistics is gathered. It will either (1) send netlink messages for RTM_GETSTATS/RTM_NEWSTATS, or (2) open files in /sys, or (3) using iocl for SIOCGPPPSTATS.

ioctl was the old mechanism pre 2.5 and only supports 32-bit counters. RTM_GETSTATS is only available on new enough kernels, and sysfs uses file parsing.

Kernel version would also help.

@Neustradamus
Copy link
Member

@gerickson: Have you seen comments from @paulusmack and @jkroonza?

Thanks in advance.

@gerickson
Copy link
Author

I hadn't seen the comments above until just now. The underlying kernel version is invariant, 4.9.212 from Digi Embedded Yocto (DEY) 2.6, across the changed in ppp version.

The underlying connection is over a serial link (serial port /dev/ttyUSB3) to a NimbleLink (Quectel) LTE CAT-1M cellular modem.

I'll see about gathering the other data shortly.

@gerickson
Copy link
Author

If it's a helpful bit of data, I've attached the following from the build:

  • config.cache
  • config.log
  • config.status
  • pppd/config.h
  • pppd/pppdconf.h

@gerickson
Copy link
Author

I just ran a quick data test. Here are the system logs from pppd for that run:

Nov 10 17:01:59 19205519 daemon.notice pppd[485]: pppd 2.5.0 started by root, uid 0
Nov 10 17:02:00 19205519 daemon.debug pppd[485]: Script chat -v -f /etc/ppp/scripts/connect-verizon finished (pid 619), status = 0x2
Nov 10 17:02:00 19205519 daemon.err pppd[485]: Connect script failed
Nov 10 17:02:01 19205519 daemon.info pppd[485]: Hangup (SIGHUP)
Nov 10 17:02:01 19205519 daemon.err pppd[485]: Failed to open /dev/ttyUSB3: No such file or directory
Nov 10 17:02:02 19205519 daemon.err pppd[485]: Failed to open /dev/ttyUSB3: No such file or directory
Nov 10 17:02:03 19205519 daemon.err pppd[485]: Failed to open /dev/ttyUSB3: No such file or directory
Nov 10 17:02:04 19205519 daemon.err pppd[485]: Failed to open /dev/ttyUSB3: No such file or directory
Nov 10 17:02:09 19205519 daemon.debug pppd[485]: Script chat -v -f /etc/ppp/scripts/connect-verizon finished (pid 628), status = 0x0
Nov 10 17:02:09 19205519 daemon.info pppd[485]: Serial connection established.
Nov 10 17:02:09 19205519 daemon.debug pppd[485]: using channel 1
Nov 10 17:02:09 19205519 daemon.info pppd[485]: Using interface ppp0
Nov 10 17:02:09 19205519 daemon.notice pppd[485]: Connect: ppp0 <--> /dev/ttyUSB3
Nov 10 17:02:19 19205519 daemon.warn pppd[485]: Warning - secret file /etc/ppp/pap-secrets has world and/or group access
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xa0f94b6e> <pcomp> <accomp>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xfacd807d> <pcomp> <accomp>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: No auth is possible
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [LCP ConfRej id=0x0 <auth chap MD5>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xa0f94b6e> <pcomp> <accomp>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xfacd807d> <pcomp> <accomp>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xfacd807d> <pcomp> <accomp>]
Nov 10 17:02:19 19205519 daemon.warn pppd[485]: kernel does not support PPP filtering
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [LCP DiscReq id=0x2 magic=0xfacd807d]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [LCP ProtRej id=0x3 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [IPCP ConfReq id=0x0]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [IPCP ConfReq id=0x1]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPCP ConfAck id=0x1]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [IPCP ConfNak id=0x2 <addr 100.98.197.33> <ms-dns1 198.224.174.135> <ms-dns2 198.224.173.135>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: sent [IPCP ConfReq id=0x3 <addr 100.98.197.33> <ms-dns1 198.224.174.135> <ms-dns2 198.224.173.135>]
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: rcvd [IPCP ConfAck id=0x3 <addr 100.98.197.33> <ms-dns1 198.224.174.135> <ms-dns2 198.224.173.135>]
Nov 10 17:02:19 19205519 daemon.warn pppd[485]: Could not determine remote IP address: defaulting to 10.64.64.64
Nov 10 17:02:19 19205519 daemon.err pppd[485]: Failed to create /etc/ppp/resolv.conf: Read-only file system
Nov 10 17:02:19 19205519 daemon.notice pppd[485]: local  IP address 100.98.197.33
Nov 10 17:02:19 19205519 daemon.notice pppd[485]: remote IP address 10.64.64.64
Nov 10 17:02:19 19205519 daemon.notice pppd[485]: primary   DNS address 198.224.174.135
Nov 10 17:02:19 19205519 daemon.notice pppd[485]: secondary DNS address 198.224.173.135
Nov 10 17:02:19 19205519 daemon.debug pppd[485]: Script /etc/ppp/ip-up started (pid 640)
Nov 10 17:02:20 19205519 daemon.debug pppd[485]: Script /etc/ppp/ip-up finished (pid 640), status = 0x0
Nov 10 17:02:22 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:25 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:28 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:31 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:34 19205519 daemon.debug pppd[485]: sent [IPV6CP ConfReq id=0x1 <addr fe80::fd5d:35b6:1117:aace>]
Nov 10 17:02:36 19205519 daemon.info pppd[485]: Terminating on signal 15
Nov 10 17:02:36 19205519 daemon.info pppd[485]: Connect time 0.3 minutes.
Nov 10 17:02:36 19205519 daemon.info pppd[485]: Sent 5030484 bytes, received 1312 bytes.
Nov 10 17:02:36 19205519 daemon.debug pppd[485]: Script /etc/ppp/ip-down started (pid 684)
Nov 10 17:02:36 19205519 daemon.debug pppd[485]: sent [LCP TermReq id=0x2 "User request"]
Nov 10 17:02:36 19205519 daemon.debug pppd[485]: rcvd [LCP TermAck id=0x2]
Nov 10 17:02:36 19205519 daemon.notice pppd[485]: Connection terminated.
Nov 10 17:02:36 19205519 daemon.debug pppd[485]: Script chat -v -f /etc/ppp/scripts/disconnect finished (pid 694), status = 0x0
Nov 10 17:02:36 19205519 daemon.info pppd[485]: Serial link disconnected.
Nov 10 17:02:37 19205519 daemon.debug pppd[485]: Script /etc/ppp/ip-down finished (pid 684), status = 0x0
Nov 10 17:02:37 19205519 daemon.info pppd[485]: Exit.

For a quick ICMP_V4_ECHO_REQUEST and ICMP_V4_ECHO_REPLY, I very much doubt 5,030,484 bytes were sent.

Here's the same output from ifconfig after that run:

ppp0      Link encap:Point-to-Point Protocol  
          inet addr:100.98.197.33  P-t-P:10.64.64.64  Mask:255.255.255.255
          UP POINTOPOINT RUNNING NOARP MULTICAST  MTU:1500  Metric:1
          RX packets:15 errors:0 dropped:0 overruns:0 frame:0
          TX packets:22 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:3 
          RX bytes:938 (938.0 B)  TX bytes:1375 (1.3 KiB)

which seems slightly more credible.

@enaess
Copy link
Contributor

enaess commented Nov 11, 2023

Honestly, it sounds like a regression and I am probably the one to blame. Haven't had any bandwidth to look at this yet. I'd still vouch for getting this fixed for 2.5.1 goes out the door

@jkroonza
Copy link
Contributor

@gerickson I actually wonder if I might not be the one to blame to be honest. I did the refactoring to allow for 64-bit counters, @enaess did a lot of work on ppp 2.5.0 as well, but this just feels more likely related to:

commit 81ad945630120cc1c27c8bb00503be42b76ff202
Author: Jaco Kroon <jaco@uls.co.za>
Date:   Thu Jan 13 08:38:04 2022 +0200

    Expand byte count statistics to 64 bits (#298)

Could you please get me the output from strace attached to the ppp process during shutdown? Ie:

strace -p $(pidof pppd)

Then initiate a shutdown on the pppd process. Copy & paste the output on the strace side please. Possibly you could do something like (off the top of my head):

real_pppd_path=$(which pppd)
mv ${real_pppd_path} ${real_pppd_path}.real
cat > ${real_pppd_path} <<<WRAPPER
#! /bin/sh

exec strace ${real_pppd_path}.real "$@" 2>/tmp/strace-pppd-$(date +%s).txt
WRAPPER
chmod 755 ${real_pppd_path}

After which all invocations of pppd will result in the original pppd binary being run inside strace with the system calls logged to /tmp/strace-pppd-${timestamp}.txt

To undo simply rename .real back to the original name.

@gerickson
Copy link
Author

Regrettably, I haven't had the bandwidth to circle back to this as of yet.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

5 participants