mosh-client crashed in update_assumed_receiver_state upon device wake
I had four mosh-client processes running when I opened my laptop this morning after leaving home, and one of them crashed immediately while the others kept working like they usually do. The laptop didn't have a usable network link when I opened it. The other side is a Ubuntu 16.04.5 LTS with whatever mosh-version is included there.
Here's the complete crash log.
Process: mosh-client [9500]
Path: /usr/local/Cellar/mosh/1.3.2_4/bin/mosh-client
Identifier: mosh-client
Version: 0
Code Type: X86-64 (Native)
Parent Process: ??? [9499]
Responsible: mosh-client [9500]
User ID: 501
Date/Time: 2018-11-07 07:31:06.209 +0100
OS Version: Mac OS X 10.14.1 (18B75)
Report Version: 12
Bridge OS Version: 3.1 (16P1065)
Anonymous UUID: 25720A49-0E1F-1028-0A95-AF0A739D5C54
Sleep/Wake UUID: FE4D84F4-85CB-4CE9-AF35-A9DBFFD34E85
Time Awake Since Boot: 450000 seconds
Time Since Wake: 1 seconds
System Integrity Protection: enabled
Crashed Thread: 0 Dispatch queue: com.apple.main-thread
Exception Type: EXC_CRASH (SIGABRT)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Exception Note: EXC_CORPSE_NOTIFY
Application Specific Information:
dyld2 mode
Assertion failed: (now >= i->timestamp), function update_assumed_receiver_state, file ./../network/transportsender-impl.h, line 283.
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0 libsystem_kernel.dylib 0x00007fff7bb09b86 __pthread_kill + 10
1 libsystem_pthread.dylib 0x00007fff7bbbfc50 pthread_kill + 285
2 libsystem_c.dylib 0x00007fff7ba731c9 abort + 127
3 libsystem_c.dylib 0x00007fff7ba3b868 __assert_rtn + 320
4 mosh-client 0x000000010ea7a9b0 Network::TransportSender
5 mosh-client 0x000000010ea7a6f7 Network::TransportSender
6 mosh-client 0x000000010ea7ab85 Network::TransportSender
7 mosh-client 0x000000010ea77224 STMClient::main() + 2556
8 mosh-client 0x000000010ea72735 main + 437
9 libdyld.dylib 0x00007fff7b9cb08d start + 1
Thread 0 crashed with X86 Thread State (64-bit):
rax: 0x0000000000000000 rbx: 0x0000000113d405c0 rcx: 0x00007ffee118ebf8 rdx: 0x0000000000000000
rdi: 0x0000000000000307 rsi: 0x0000000000000006 rbp: 0x00007ffee118ec30 rsp: 0x00007ffee118ebf8
r8: 0x000000000000011b r9: 0xcccccccccccccccd r10: 0x0000000000000000 r11: 0x0000000000000206
r12: 0x0000000000000307 r13: 0x000000010f11d000 r14: 0x0000000000000006 r15: 0x000000000000002d
rip: 0x00007fff7bb09b86 rfl: 0x0000000000000206 cr2: 0x00007fffae7d2188
Logical CPU: 0
Error Code: 0x02000148
Trap Number: 133
Binary Images:
0x10ea70000 - 0x10eaabff7 +mosh-client (0) <27B8877C-023F-35BA-A874-0FE227D1A2E8> /usr/local/Cellar/mosh/1.3.2_4/bin/mosh-client
0x10ead4000 - 0x10ebfefeb +libprotobuf.17.dylib (0) <681916E6-DECE-3CD8-979F-E47FEF2BFEBA> /usr/local/opt/protobuf/lib/libprotobuf.17.dylib
0x113c8a000 - 0x113d086a7 dyld (635.2) <1780094A-8FE2-3EAA-B4A3-C4CF14BC5196> /usr/lib/dyld
0x7fff78e40000 - 0x7fff78e41ffb libSystem.B.dylib (1252.200.5)
0x7fff7909a000 - 0x7fff790f1ff7 libc++.1.dylib (400.9.4)
0x7fff790f2000 - 0x7fff79107fff libc++abi.dylib (400.17)
0x7fff7a32a000 - 0x7fff7a35aff7 libncurses.5.4.dylib (53.200.3)
0x7fff7a8e6000 - 0x7fff7b06cfe7 libobjc.A.dylib (750.1) <9CE27EC3-3A12-35D1-8F2F-3550B9668259> /usr/lib/libobjc.A.dylib
0x7fff7b7c9000 - 0x7fff7b7dbffb libz.1.dylib (70.200.4) <99A3D725-8388-38B4-B66C-5E9006E6F072> /usr/lib/libz.1.dylib
0x7fff7b84c000 - 0x7fff7b850ff3 libcache.dylib (81)
0x7fff7b851000 - 0x7fff7b85bff3 libcommonCrypto.dylib (60118.220.1) <1099E427-6E81-3059-87AF-6F5FD81CA998> /usr/lib/system/libcommonCrypto.dylib
0x7fff7b85c000 - 0x7fff7b863fff libcompiler_rt.dylib (63.4)
0x7fff7b864000 - 0x7fff7b86dff3 libcopyfile.dylib (146.200.3) <4BCDADBF-79F5-3829-B47D-64DA0D44BCBF> /usr/lib/system/libcopyfile.dylib
0x7fff7b86e000 - 0x7fff7b8f2fdf libcorecrypto.dylib (602.220.6)
0x7fff7b979000 - 0x7fff7b9b3ff7 libdispatch.dylib (1008.220.2)
0x7fff7b9b4000 - 0x7fff7b9e3fff libdyld.dylib (635.2) <1B79A5CE-125F-301F-A441-C1869573AED0> /usr/lib/system/libdyld.dylib
0x7fff7b9e4000 - 0x7fff7b9e4ffb libkeymgr.dylib (30)
0x7fff7b9f2000 - 0x7fff7b9f2ff7 liblaunch.dylib (1336.220.5) <95EB6EAF-2DC5-344F-BADB-CA4E35E4E503> /usr/lib/system/liblaunch.dylib
0x7fff7b9f3000 - 0x7fff7b9f8fff libmacho.dylib (921)
0x7fff7b9f9000 - 0x7fff7b9fbffb libquarantine.dylib (86.220.1) <6AE5AEEC-A9FD-3CF8-92DD-12B5AFBE12DE> /usr/lib/system/libquarantine.dylib
0x7fff7b9fc000 - 0x7fff7b9fdff3 libremovefile.dylib (45.200.2)
0x7fff7b9fe000 - 0x7fff7ba15ff3 libsystem_asl.dylib (356.200.4)
0x7fff7ba16000 - 0x7fff7ba16fff libsystem_blocks.dylib (73) <26419398-C30C-30F1-B656-A92AFA9560F6> /usr/lib/system/libsystem_blocks.dylib
0x7fff7ba17000 - 0x7fff7ba9ffff libsystem_c.dylib (1272.200.26) <3DEEE96E-6DF6-35AD-8654-D69AC26B907B> /usr/lib/system/libsystem_c.dylib
0x7fff7baa0000 - 0x7fff7baa3ff7 libsystem_configuration.dylib (963.200.27) <02CC3996-B34E-333C-8806-AE2699D34424> /usr/lib/system/libsystem_configuration.dylib
0x7fff7baa4000 - 0x7fff7baa7ff7 libsystem_coreservices.dylib (66) <254B6849-2C8F-302C-8616-B8324A11AB30> /usr/lib/system/libsystem_coreservices.dylib
0x7fff7baa8000 - 0x7fff7baaeffb libsystem_darwin.dylib (1272.200.26) <974E9EF7-DE72-34B7-B056-0A81C10DF8EB> /usr/lib/system/libsystem_darwin.dylib
0x7fff7baaf000 - 0x7fff7bab5ff7 libsystem_dnssd.dylib (878.200.35)
0x7fff7bab6000 - 0x7fff7bb02ff3 libsystem_info.dylib (517.200.9) <0707C387-D7DE-372E-8FF1-3DE5C91932D6> /usr/lib/system/libsystem_info.dylib
0x7fff7bb03000 - 0x7fff7bb2aff7 libsystem_kernel.dylib (4903.221.2) <0E882078-7330-3B49-AA5D-3CDB5645A4E5> /usr/lib/system/libsystem_kernel.dylib
0x7fff7bb2b000 - 0x7fff7bb76ff7 libsystem_m.dylib (3158.200.7) <43D1796B-954F-37D6-B1AC-9D80DF0655A2> /usr/lib/system/libsystem_m.dylib
0x7fff7bb77000 - 0x7fff7bb9bff7 libsystem_malloc.dylib (166.220.1) <3B196122-4E0D-3E3F-AA3E-5115B976DE26> /usr/lib/system/libsystem_malloc.dylib
0x7fff7bb9c000 - 0x7fff7bba7ff3 libsystem_networkextension.dylib (767.220.1)
0x7fff7bba8000 - 0x7fff7bbaffff libsystem_notify.dylib (172.200.21)
0x7fff7bbb0000 - 0x7fff7bbb9fef libsystem_platform.dylib (177.200.16)
0x7fff7bbba000 - 0x7fff7bbc4fff libsystem_pthread.dylib (330.220.2) <4958273C-4273-3501-8137-E44249E10D9C> /usr/lib/system/libsystem_pthread.dylib
0x7fff7bbc5000 - 0x7fff7bbc8ff7 libsystem_sandbox.dylib (851.220.9) <4D6433A8-C703-3ED9-82EB-B9E481A0FD2F> /usr/lib/system/libsystem_sandbox.dylib
0x7fff7bbc9000 - 0x7fff7bbcbff3 libsystem_secinit.dylib (30.220.1) <6C681113-8C48-3256-BEF6-0C3723DEB926> /usr/lib/system/libsystem_secinit.dylib
0x7fff7bbcc000 - 0x7fff7bbd3ff7 libsystem_symptoms.dylib (820.227.2) <3147D594-F41F-35FD-BF0B-6B8B66A407DE> /usr/lib/system/libsystem_symptoms.dylib
0x7fff7bbd4000 - 0x7fff7bbe9ff7 libsystem_trace.dylib (906.220.1)
0x7fff7bbeb000 - 0x7fff7bbf0ffb libunwind.dylib (35.4) <41222EF6-2233-3CF4-947A-15D48CB8C030> /usr/lib/system/libunwind.dylib
0x7fff7bbf1000 - 0x7fff7bc21fff libxpc.dylib (1336.220.5)
External Modification Summary:
Calls made by other processes targeting this process:
task_for_pid: 106
thread_create: 0
thread_set_state: 0
Calls made by this process:
task_for_pid: 0
thread_create: 0
thread_set_state: 0
Calls made by all processes on this machine:
task_for_pid: 452177
thread_create: 0
thread_set_state: 0
VM Region Summary:
ReadOnly portion of Libraries: Total=230.4M resident=0K(0%) swapped_out_or_unallocated=230.4M(100%)
Writable regions: Total=120.3M written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=120.3M(100%)
VIRTUAL REGION
REGION TYPE SIZE COUNT (non-coalesced)
=========== ======= =======
Kernel Alloc Once 8K 2
MALLOC 112.1M 11
MALLOC guard page 16K 5
STACK GUARD 56.0M 2
Stack 8192K 2
VM_ALLOCATE 4K 2
__DATA 2320K 44
__LINKEDIT 217.0M 5
__TEXT 13.4M 43
shared memory 12K 4
=========== ======= =======
TOTAL 408.8M 110
Model: MacBookPro15,1, BootROM 220.220.102.0.0 (iBridge: 16.16.1065.0.0,0), 6 processors, Intel Core i9, 2,9 GHz, 32 GB, SMC
Graphics: Intel UHD Graphics 630, Intel UHD Graphics 630, Built-In
Graphics: Radeon Pro 560X, Radeon Pro 560X, PCIe
Memory Module: BANK 0/ChannelA-DIMM0, 16 GB, DDR4, 2400 MHz, Micron, 16ATS2G64HZ-2G6B1 16ATS2G64HZ-2G6B1
Memory Module: BANK 2/ChannelB-DIMM0, 16 GB, DDR4, 2400 MHz, Micron, 16ATS2G64HZ-2G6B1 16ATS2G64HZ-2G6B1
AirPort: spairport_wireless_card_type_airport_extreme (0x14E4, 0x7BF), wl0: Sep 18 2018 16:24:57 version 9.130.86.7.32.6.21 FWID 01-83a3fe91
Bluetooth: Version 6.0.9f2, 3 services, 27 devices, 1 incoming serial ports
Network Service: Wi-Fi, AirPort, en0
Network Service: VPN SDAG, PPP (L2TP)
USB Device: USB 3.1 Bus
USB Device: iBridge Bus
USB Device: iBridge DFR brightness
USB Device: iBridge Display
USB Device: Apple Internal Keyboard / Trackpad
USB Device: Headset
USB Device: iBridge ALS
USB Device: iBridge FaceTime HD Camera (Built-in)
USB Device: iBridge
Thunderbolt Bus: MacBook Pro, Apple Inc., 34.6
Thunderbolt Bus: MacBook Pro, Apple Inc., 34.6
maiksd
All 39 comments
I've now seen this at least once (I think it just happened again, but didn't see the assert message this time) on a MacBookPro15,2 and MacOS 10.14.2. The obvious inference is that MacOS has a clock_gettime(...CLOCK_MONOTONIC...) that is not actually monotonic during sleep/wake, but this needs confirmation. That would be Apple's fault but still our problem.
I opened/woke a laptop which then brought up WiFi (with EAP authentication) and also tried to reconnect a VPN, which failed. I happened to have 3 mosh clients running; only one of them died.
Perhaps we could defend against flaky clocks by using the last-queried time until the newly-queried time is actually later.
cgull
on 7 Feb 2019
Oh, I wasn't even aware this results in a github issue. Nice.
I have this type of crash every now and then. Should I pay attention to something in particular next time, or gather any specific logs or other information?
maiksd
on 7 Feb 2019
One thing I just thought of: when you woke the Mac, did you open (and wake) it, then authenticate (with Touch ID or password)? Or was it already open but sleeping, and you woke/authenticated it with Touch ID? I wonder if the much faster wake+authenticate with Touch ID is playing a role here. (But my last crash was probably after opening the laptop.)
If we can get a semi-reliable way to reproduce the problem, it'll be easier to debug and fix.
cgull
on 7 Feb 2019
It is usually closed, then it resumes upon lid-open. There is authentication, but it happens quickly (using Apple Watch proximity authentication). That's usually even quicker than reaching for Touch ID.
maiksd
on 7 Feb 2019
Oh, interesting, I hadn't even thought of Watch-based authentication. How long does that take, from first starting to open the lid, to your desktop appearing? Touch ID on an sleeping but open laptop is under 1 second.
cgull
on 7 Feb 2019
Sometimes it takes a few seconds for whatever reason, but usually I open the lid, and the moment the display lights up my watch often already taps me with the message that it's been authenticating the login (a bit slower with older watch models though, this is a series 4).
maiksd
on 7 Feb 2019
I have been running into this several times a day, all week. Is there anything I can do to help debug?
I usually do not close the lid, and I am unlocking with Apple Watch.
ghazel
on 10 May 2019
I'm seeing fairly large differences in timestamp values:
now:442665872 i->timestamp:443240701
ghazel
on 14 May 2019
I forced mosh to use mach_absolute_time() instead of clock_gettime(CLOCK_MONOTONIC, ...) and this problem went away.
ghazel
on 4 Jun 2019
That's great -- thank you! Do you feel up to filing a pull request that
fixes our clock implementation on Mac (and I guess also filling a big with
Apple since this sounds like a macOS bug)?
On Tue, Jun 4, 2019, 2:50 PM Greg Hazel notifications@github.com wrote:
I forced mosh to use mach_absolute_time() instead of clock_gettime(CLOCK_MONOTONIC,
...) and this problem went away.—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/mobile-shell/mosh/issues/1014?email_source=notifications&email_token=AABTAOZYGDZGK5WC7GILSE3PY3PQZA5CNFSM4GCHV2UKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODW57F4I#issuecomment-498856689,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AABTAOYHGQLQQVIUIJZLZ6TPY3PQZANCNFSM4GCHV2UA
.
keithw
on 4 Jun 2019
This is from the clock_gettime man page on macOS:
CLOCK_MONOTONIC clock that increments monotonically, tracking the time
since an arbitrary point, and will continue to increment
while the system is asleep.
So if I understand this correctly, the large time difference with CLOCK_MONOTONIC right after sleeping is the intended behaviour.
Luflosi
on 5 Jun 2019
It's a large negative difference, though.
ghazel
on 5 Jun 2019
Oh, then I have no explanation. Sorry for the noise.
Luflosi
on 5 Jun 2019
That's great -- thank you! Do you feel up to filing a pull request that fixes our clock implementation on Mac (and I guess also filling a big with Apple since this sounds like a macOS bug)?
…
I don't have a sufficiently small reproduction of the bug to submit to Apple. I also don't have time (hah) to submit a proper pull request. You're welcome to my diff, though:
diff --git a/src/util/timestamp.cc b/src/util/timestamp.cc
index 2e2efe2..9219b10 100644
--- a/src/util/timestamp.cc
+++ b/src/util/timestamp.cc
@@ -71,7 +71,7 @@ void freeze_timestamp( void )
if (
#if defined(__APPLE__) && defined(__MACH__)
// Check for presence, for OS X SDK >= 10.12 and runtime < 10.12
- &clock_gettime != NULL &&
+ false &&
#endif
clock_gettime( CLOCK_MONOTONIC, &tp ) == 0 ) {
uint64_t millis = tp.tv_nsec / 1000000;
same problem, very annoying.
Assertion failed: (now >= i->timestamp), function update_assumed_receiver_state, file ./../network/transportsender-impl.h
oiwn
on 12 Nov 2019
i happening for me for both old/new macbook airs, and after one client fail with error i can't reconnect to the server without killing other clients.
oiwn
on 19 Nov 2019
Assertion failed: (now >= i->timestamp), function update_assumed_receiver_state, file ./../network/transportsender-impl.h, line 283.
Happened once Macbook Pro 16" (2019), it was on for 4h without any sleep in between.
Emzy
on 6 May 2020
any news?
oiwn
on 28 Jul 2020
In March I started working from home, logged into a brand new Mac Mini running macOS Catalina (now at version 10.15.6). I have eight terminal windows which have mosh connections into a freebsd VM in my office. Both the Mac and my freebsd host are running mosh 1.3.2 [build mosh 1.3.2]
I see this (now >= i->timestamp) error a few times a week. My Mac Mini never goes to sleep. The display will be turned off, and it (the display) may go into power-off (energy-saver) mode by itself. But the OS as a whole does not go to sleep. The computer is running some monitoring functions which remain active 24/7 (and in fact all my mosh sessions are active 24/7). I have also seen this error pop up when even the display is not asleep.
I have to apologize that I have not had any time to look into the code for mosh. Is this timestamp error totally on the local system, or could it be caused by garbled data coming from the remote side of the connection?
So I have eight mosh sessions active, all going from the one Mac to the same FreeBSD server at work. In the past 7 days, I see and average of two crashes per day where I see this (now >= i->timestamp) error come up on the Mac side. About once every two weeks the copy of mosh on the freebsd side will crash, but I have no idea what the error is on that side. (the FreeBSD server is actually running as a VMware-based VM on a Mac in my office, if that's of any interest).
drosehn
on 30 Sep 2020
Maybe I should also mention that these mosh connections are going through a Cisco VPN connection on my Mac, and of course my Mac is behind a cable modem so these connections also have a layer of NAT going on.
In any case, is there any further progress on this issue? Is it only macOS users who run into it?
drosehn
on 30 Sep 2020
Back in Nov 2019, oiwn wrote:
i happening for me for both old/new macbook airs, and after one client fail with error i can't reconnect to the server without killing other clients.
In my case, all I have to do is restart the mosh session which has died. I do have an extra layer there, too, in that I'm actually starting these sessions using a program I wrote. So that program runs mosh, and if it notices that the tty-settings are screwed up then it resets the tty to what it was before mosh started. But then my program asks me what I want to do, and I just hit "enter" to launch another mosh session with all the same parameters as the session which had just died.
But all I have to do is restart the session which had died. All the other mosh sessions are running fine, and I can create multiple new mosh sessions on my mac without killing off any of the existing ones.
drosehn
on 30 Sep 2020
I just had this happen to me as well on an 2020 iMac with MacOS 10.15.7.
mikaabra
on 15 Oct 2020
Repeating my comment from June 2019 (https://github.com/mobile-shell/mosh/issues/1014#issuecomment-498857466) -- we're looking for somebody to (a) file this bug with Apple and track it, since it does seem to be a MacOS bug, and (b) submit a pull request for a workaround in Mosh.
keithw
on 15 Oct 2020
I have reported this to apple and their "feedback" identifier (in their bug reporting tool) is FB8801999.
mikaabra
on 15 Oct 2020
I've been trying to collect some data on the crashes I'm seeing, because I want to be sure I understand what's happening. I have my own vague suspicions of what might be happening, based on some problems I see on plain ssh sessions (sessions which aren't using mosh at all). I haven't had much time to look into it though. I do have my own custom error message for when this problem happens, and here's an example output from my error message:
Assertion failed: (now >= i->timestamp), file transportsender-impl.h, line 286
#dbg: (now) 535110.531 0x'00000000 1fe52383'
#dbg: < 535110.628 0x'00000000 1fe523e4' (i->timestamp)
#dbg: (alt_now) 535133.051 0x'00000000 1fe57b7b'
now is the value of now obtained by calling clock_gettime(), while alt_now is the value obtained by calling mach_absolute_time(). While those values are pretty far apart (about 23 seconds in this case), the value in i->timestamp is actually quite close to the value of now from clock_gettime(). In all the examples I have so far, the value in i->timestamp is never more than 100 milliseconds larger than now, and in several cases it's exactly 100 milliseconds larger.
Not that that proves anything, but I think it's interesting. Others have commented that there's a "large negative difference", but that's the difference between the two values for "now". That's not the difference between the value of now from clock_gettime() and the timestamp that the code is looking at. It might be interesting to try a standalone program which just compares the two values (clock_gettime() vs mach_absolute_time()), and see how much of a difference there is between them.
drosehn
on 15 Oct 2020
And at least in my case, these crashes have nothing to do with my Mac going to sleep. I am absolutely positive this Mac Mini is not going to sleep, at all, ever. _(Except last week when my house lost power for 16 hours...)_
I've had some of my mosh sessions die while I was sitting at the computer, and actively typing into other applications. The Mac Mini is running macOS Catalina, if that might be significant.
drosehn
on 15 Oct 2020
Probably a red-herring, but it is perhaps interesting to note:
const int ACK_DELAY = 100;
(I have no experience in writing network code or in writing C++, so I'm just guessing my way through this when I have some spare time for guessing)
drosehn
on 15 Oct 2020
So I wrote a stand-alone program to compare the two counters. The difference between the two counters does fluctuate, and in fact can fluctuate by more than a second over a few hours. One run:
mach_absolute_time(start) vs. clock_gettime(start):
606_831.224 == 0x'00000000 242b8278' ; mach_absolute_time()
- 606_805.660 == 0x'00000000 242b1e9c' ; clock_gettime()
= 25.564 ; (diff)
- - - - - - - - - - - - - - - -
mach_absolute_time(end) vs. clock_gettime(end):
606_834.227 == 0x'00000000 242b8e33' ; mach_absolute_time()
- 606_808.662 == 0x'00000000 242b2a56' ; clock_gettime()
= 25.565 ; (diff)
a later run:
mach_absolute_time(start) vs. clock_gettime(start):
642_428.859 == 0x'00000000 264aafbb' ; mach_absolute_time()
- 642_401.819 == 0x'00000000 264a461b' ; clock_gettime()
= 27.040 ; (diff)
- - - - - - - - - - - - - - - -
mach_absolute_time(end) vs. clock_gettime(end):
642_430.859 == 0x'00000000 264ab78b' ; mach_absolute_time()
- 642_403.819 == 0x'00000000 264a4deb' ; clock_gettime()
= 27.040 ; (diff)
I now have an over-engineered program which makes comparisons between clock_gettime() and mach_absolute_time(). What's happening on my Mac Mini is that the value returned from mach_absolute_time() increases at a slightly faster pace than the value from clock_gettime(). It's a pretty slow but steady increase, not the "fluctuations" that I initially assumed. Here's the output of a 12-hour run of my program:
On Oct 19 2020:
- - - - - - - - - - - - -\
19:30:00, up 10d 21h 57m: mach_AT() is 39.791 secs larger
20:00:00, up 10d 22h 27m: mach_AT() is 39.863 secs larger [ 0.072 ]
20:30:00, up 10d 22h 57m: mach_AT() is 39.936 secs larger [ 0.073 ]
21:00:00, up 10d 23h 27m: mach_AT() is 40.009 secs larger [ 0.073 ]
21:30:00, up 10d 23h 57m: mach_AT() is 40.083 secs larger [ 0.074 ]
22:00:00, up 11d 0h 27m: mach_AT() is 40.158 secs larger [ 0.075 ]
22:30:00, up 11d 0h 57m: mach_AT() is 40.235 secs larger [ 0.077 ]
23:00:00, up 11d 1h 27m: mach_AT() is 40.313 secs larger [ 0.078 ]
23:30:00, up 11d 1h 57m: mach_AT() is 40.392 secs larger [ 0.079 ]
On Oct 20 2020:
- - - - - - - - - - - - -\
00:00:00, up 11d 2h 27m: mach_AT() is 40.469 secs larger [ 0.077 ]
00:30:00, up 11d 2h 57m: mach_AT() is 40.545 secs larger [ 0.076 ]
01:00:00, up 11d 3h 27m: mach_AT() is 40.621 secs larger [ 0.076 ]
01:30:00, up 11d 3h 57m: mach_AT() is 40.696 secs larger [ 0.075 ]
02:00:01, up 11d 4h 27m: mach_AT() is 40.771 secs larger [ 0.075 ]
02:30:01, up 11d 4h 57m: mach_AT() is 40.844 secs larger [ 0.073 ]
03:00:01, up 11d 5h 27m: mach_AT() is 40.917 secs larger [ 0.073 ]
03:30:01, up 11d 5h 57m: mach_AT() is 40.993 secs larger [ 0.076 ]
04:00:01, up 11d 6h 27m: mach_AT() is 41.072 secs larger [ 0.079 ]
04:30:01, up 11d 6h 57m: mach_AT() is 41.152 secs larger [ 0.080 ]
05:00:01, up 11d 7h 27m: mach_AT() is 41.233 secs larger [ 0.081 ]
05:30:01, up 11d 7h 57m: mach_AT() is 41.313 secs larger [ 0.080 ]
06:00:01, up 11d 8h 27m: mach_AT() is 41.393 secs larger [ 0.080 ]
06:30:01, up 11d 8h 57m: mach_AT() is 41.472 secs larger [ 0.079 ]
07:00:01, up 11d 9h 27m: mach_AT() is 41.549 secs larger [ 0.077 ]
07:30:01, up 11d 9h 57m: mach_AT() is 41.629 secs larger [ 0.080 ]
-------------------------------------------------------
-----| ToD in millis | Mach millis | ToD minus Mach
end: 88_428_601.632 - 986_274.397 = 87_442_327.235
start: 88_385_400.293 - 943_074.274 = 87_442_326.019
diffs: 43_201.339 - 43_200.123 = 1.216
-----| (tod's adjusted to be based on Jan 1, 2018)
-------------------------------------------------------
After 12h 0m 1.33s, the mach-vs-clock diff has gone from
39.791 to 41.629 secs.
The number in square brackets is how much the difference between mach_AT and clock_GT has changed since the previous line. So mach_AT's time is increasing faster than clock_GT's time by a pretty steady average of 0.076 seconds every 30 minutes, for a total of 1.83 seconds over 12 hours. I got curious how that would compare to the wall-clock time returned by gettimeofday(), so I added that comparison-table at the end. gettimeofday() isn't guaranteed to be monotonically-increasing, of course, so I don't know if we can draw any conclusions from that little table. But I thought it was interesting that the value from gettimeofday() increased another 1.216 seconds over the value from mach_absolute_time() during the same 12 hours.
I could upload the source for my program, if anyone's interested.
drosehn
on 20 Oct 2020
Meanwhile, the most recent mosh crashes that I've seen have a 'diff'erence between the clock_gettime()-based now and i->timestamp which look like:
#dbg: == 0.104 == 0x'00000000 00000068' (diff)
#dbg: == 0.082 == 0x'00000000 00000052' (diff)
#dbg: == 0.103 == 0x'00000000 00000067' (diff)
#dbg: == 0.093 == 0x'00000000 0000005d' (diff)
#dbg: == 0.104 == 0x'00000000 00000068' (diff)
#dbg: == 0.097 == 0x'00000000 00000061' (diff)
#dbg: == 0.018 == 0x'00000000 00000012' (diff)
#dbg: == 0.088 == 0x'00000000 00000058' (diff)
#dbg: == 0.103 == 0x'00000000 00000067' (diff)
#dbg: == 0.098 == 0x'00000000 00000062' (diff)
#dbg: == 0.066 == 0x'00000000 00000042' (diff)
#dbg: == 0.089 == 0x'00000000 00000059' (diff)
#dbg: == 0.101 == 0x'00000000 00000065' (diff)
Each line is from a different crash of mosh. Let's assume mach_absolute_time() is the correct time. It seems to me that if clock_gettime() is slow by 152 milliseconds per hour, then there's more than that going on to explain how mosh is seeing values of now which are as much as 104 milliseconds lower than the values in i->timestamp.
Note that my earlier comment of the value in i->timestamp is never more than 100 milliseconds larger than now, is not accurate. I want to collect more info from these mosh-crashes before making any conclusions. I've already had a few plausible theories which have been shot down by what I've collected so far!
drosehn
on 20 Oct 2020
mikaabra wrote:
I have reported this to apple and their "feedback" identifier (in their bug reporting tool) is FB8801999.
There's no way for me to view that, right? All I can do is reference that number if I submit my own bug report?
drosehn
on 20 Oct 2020
@mikaabra you could file it on Open Radar so other people can see it: https://openradar.appspot.com/FB8801999
ghazel
on 20 Oct 2020
I've been quiet for awhile here, but I thought I'd add an update. I've done some more testing (deliberately without the using above work-around), and this crash happens when I'm running mosh on my intel-based Mac Mini which is running macOS Catalina (10.15.7). It's a model from 2018 (which I bought it brand new in March 2020). It has a 3 GHz 6-Core Intel Core i5. I'm running eight copies of mosh on this machine, all of them running 24x7. I will sometimes go as many as three or four days without a crash, or I might get more than 10 crashes in a single day. A single session might see multiple crashes in the same day.
I ran the exact same source code for mosh, as compiled and running on a Macbook Pro from 2013. That laptop has a 2.6 GHz Intel Core i5. I tried it with that machine running twelve copies of mosh on macOS High Sierra. In two weeks of running these sessions 24x7, I didn't see a single crash. I should note that I had some reasons to suspect the problem was in a VPN I am using on the Mac Mini. So on the MBPro I ran both with and without the VPN, and saw no crashes.
I then installed macOS Mojave on the Macbook Pro, and ran the exact same source code for mosh as compiled on Mojave. I ran the 12 sessions for multiple weeks, both with and without the VPN, and never saw this crash in mosh. So all of this strongly suggests that the problem is either with the hardware in the newer Mac Mini (and maybe other more-recent Macs), or something specific to macOS Catalina. Or maybe some other difference I'm not thinking of, such as maybe the two machines are using two different NTP servers.
I intend to write some more changes to mosh to collect more data, and then send that data off to Apple. I do not expect to write any more updates to this issue in the mosh project, since it seems pretty unlikely that the real problem is in mosh. However, I'll first try using CLOCK_MONOTONIC_RAW on my Mac Mini (as described in issue #1124), and see if that causes the problems to go away.
drosehn
on 14 Dec 2020
I just started running into this for the first time ever, on my MacBook Pro only after upgrading to Big Sur, prior I have been using it without crash for over a year. The specs are:
MacBook Pro (16-inch, 2019)
2.6 GHz 6-Core Intel Core i7
16 GB 2667 MHz DDR4
Not that all of that matters, but for completeness sake. I have yet to update my brew install (was up to date prior to Big Sur), and was about to do that next, just to make sure its still an unfixed bug.
Output of the crash (only maybe the 3rd time this has happened on this system ever):
Assertion failed: (now >= i->timestamp), function update_assumed_receiver_state, file ./../network/transportsender-impl.h, line 283.
Abort trap: 6
Can't say for sure if this is helpful, but just in case, I figured I would chime in. I do open and close (sleep/wake) on a daily basis, and it seems to show up after wake, so I discover it in the morning when I start work.
git-jonathankinney
on 9 Feb 2021
This is still affecting OSX 11.2, and forcing the use of mach_absolute_time() still resolves the issue.
The issue has been raised with Apple, and my pull req to fix this in mosh has been pending for 6 months.
Is there any chance of this getting some love from the mosh devs?
fffe
on 24 Feb 2021
I just skimmed this issue to see if anyone else had reported this, and I didn't see it, but I could have missed it: This just happened for me (first time I've ever seen it) but I was in the middle of actively using it, not just waking up from sleep. I had been using the session for hours.
macOS 11.3 Intel
mvgrad98
on 6 May 2021
Just as an update, I've had this happen to me in the past week, on Intel iMac, running 11.3, on an active session (as in I was typing and it just happened mid-typing).
mikaabra
on 6 May 2021
I just skimmed this issue to see if anyone else had reported this, and I didn't see it, but I could have missed it: This just happened for me (first time I've ever seen it) _but_ I was in the middle of actively using it, not just waking up from sleep. I had been using the session for hours.
macOS 11.3 Intel
Issue still there, Intel MBA 10.15.7
oiwn
on 24 May 2021
I run into this regularly and it is definitely occurring outside of sleep/wake. Most recently was just now on macOS 11.4 (20F71) Intel MBP 16" 2019.
sdunster
on 16 Jun 2021
Related issues
brandonkal
·
7Comments
jiyinyiyong
·
7Comments
a-b
·
6Comments
pravi
·
5Comments
Intensity
·
7Comments
Most helpful comment
This is still affecting OSX 11.2, and forcing the use of mach_absolute_time() still resolves the issue.
The issue has been raised with Apple, and my pull req to fix this in mosh has been pending for 6 months.
Is there any chance of this getting some love from the mosh devs?