**** BEGIN LOGGING AT Thu Jun 07 03:00:04 2018 Jun 07 06:53:02 hello, I have encoutered an issue, which is 'Qmake spec does not set MAKEFILE_GENERATOR', when I cross-compile qt 5.11.0 to the beaglebone black, in a VM build server. Jun 07 06:58:48 Hi, I logged in with debian and temppwd. What is the root password for angstrom? Jun 07 07:00:13 Is the password 'root'? Jun 07 07:03:25 'rumpelstilzchen' ? Jun 07 07:07:18 lol root it was, I thought I tried that Jun 07 07:07:20 thanks Jun 07 10:08:10 hi Jun 07 10:41:48 hi Jun 07 10:59:52 I guess he just really wanted to say hi Jun 07 11:15:40 lol -smh- Jun 07 13:28:50 I'm new to the Beaglebone. I'm trying to login to the board for the first time. When I go in to Putty it's asking gor a login. I know I have to edit the sshd_config file but I can't do that without logging in to the beaglebone green Jun 07 13:44:26 ehh what? Jun 07 16:25:02 zmatt my fleet of beaglebones have all the same kind of SD cards. I set one up and then duplicate it with a copying machine. Do you think the source of my spontaneous rebooting could have something to do with a card being a copy? It seems unlikely as the copier does a copy then a verification pass but I don't know if that somehow corrupts the filesystem due to slight differences in bytes copied or something but again that would Jun 07 16:25:02 be verified by the copier so... Jun 07 16:25:30 I"m thinking it's still more likely RF interference Jun 07 16:53:21 windsurf_: I don't think you have enough information to be making guesses Jun 07 17:07:26 yeah :( Jun 07 17:08:06 OK here's another bit of information after studying the log from another occurrence of the same problem yesterday. The symptoms are consistent: Jun 07 17:10:40 zmatt so I see the reboot happen at the point in time where I got a panicked phonecall. Nothing odd in the log before that. My cell modem tries to connect (pppd) on startup. Assuming there is cell reception, which there was, this usually succeeds pretty quickly. I get some standard 'chat' output. When this problem happens though, after a spontaneous reboot, I often (always?) see at least one reconnect attempt where the chat Jun 07 17:10:40 output has some garbage in it. After that I see a normal frequency of reconnect attempts without garbage but it can never succeed. If I power cycle the device, it will boot and connect fine. Jun 07 17:13:24 here you can see two connect attempts, the first has garbage (lines 3-5) and then not on the subsequent attempts – normal example lines 45-56 Jun 07 17:13:54 Do you think the garbage is potentially indicative of RF interference or a side effect of the original unknown issue and reboot. Maybe still not enough information to say Jun 07 17:14:07 zmatt but I thought I'd ask in case your keen eye spots something Jun 07 17:14:28 https://pastebin.com/nK9cKnAQ Jun 07 17:43:57 windsurf_: sounds like the modem isn't reset when the beaglebone resets, hence you're seeing garbage from the data connection that's still active? Jun 07 17:44:40 i.e. it's just a direct consequence of the beaglebone rebooting or resetting Jun 07 17:48:02 sounds plausible. Jun 07 17:48:34 zmatt is there a command to see if my filesystem is corrupted? I tried fsck but it complained that I can't run it on the volume that's mounted and can't unmount it because I'm using it Jun 07 17:50:12 looking at kern.log, I wonder if this is normal: Jun 07 17:50:16 EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null) Jun 07 17:50:18 then two seconds later, Jun 07 17:50:26 EXT4-fs (mmcblk0p1): re-mounted. Opts: errors=remount-ro Jun 07 17:50:32 I wonder why re-mounted? Jun 07 17:57:59 just a change of options used Jun 07 17:58:03 nothing weird Jun 07 17:58:33 and I think you can boot with a certain option to force an e2fsck before the root filesystem is mounted rw Jun 07 18:04:30 I did see that option but I'm leery of it because it would make startup slower if it were needed – then again, if it's needed, I guess it's needed... Is there a way for me to know right now though if there's corruption and if it's needed, even without actually executing the repair? Jun 07 18:12:22 well there shouldn't be, but I don't think there's an easy way to double-check this Jun 07 18:13:36 k Jun 07 18:20:16 it actually looks like self repair is already set up. I only see it needing it after a forced power off (not during the unexplained reboot) Jun 07 18:20:33 which makes me think it's not the cause of my reboot Jun 07 18:20:42 that file system corruption is not the cause* Jun 07 18:21:02 when repair does kick in it looks like, Jun 07 18:21:06 INFO: recovery required on readonly filesystem Jun 07 18:21:11 recovery complete Jun 07 18:23:35 that's curious, it suggests the reboot is a reboot and not a spontaneous reset Jun 07 18:23:50 as in, a clean reboot Jun 07 18:24:45 depends what you're talking about – we've got two cases mixed into the typical timeline of the last two times this happened, a spontaneous reboot of unknown origin then on my advice the user shuts the power off ungracefully then back on Jun 07 18:25:01 the repair only happens after the ungraceful shutdown Jun 07 18:25:20 in the reboot scenario the log looks like this before the reboot and in the first part of the startup: Jun 07 18:25:37 the absence of repair in the former case means the spontaneous reboot is a clean reboot Jun 07 18:25:47 absence of journal recovery I mean Jun 07 18:26:11 so it's not a kernel panic, not a crash, not a spontaneous reset Jun 07 18:26:21 not a watchdog timeout Jun 07 18:27:16 reboot starts on line 28 here https://pastebin.com/f1YQ4iN6 Jun 07 18:27:56 ok well i'm glad to have more clues! Jun 07 18:28:08 so that means there's a programmatic restart on some level eh? Jun 07 18:28:12 although Jun 07 18:28:27 we output metrics every minute, that's what the log items are from node prefixed with *** Jun 07 18:28:40 in that you can see that it's not that we're out of storage or mem Jun 07 18:28:51 actually I'm a bit confused here Jun 07 18:29:19 ah nm Jun 07 18:29:34 or... Jun 07 18:29:36 hmm Jun 07 18:30:02 the "System clock time unset or jumped backwards" is rather weird Jun 07 18:30:11 since it shouldn't be reset unless the system is power-cycled Jun 07 18:30:51 what am I looking at here anyway? stuff is in such a bizarre order Jun 07 18:31:26 like why is there suddenly kernel log starting at line 76 ? Jun 07 18:38:20 zmatt I've been assuming that the clock jumping is expected. The device has a 3rd party RTC module and a service that upon loading sets the system time from the RTC. Prior to that, it doesn't know what the real time is. Eventually it connects to the internet (pppd) then it might make another adjustment once it talks to NTP server. So early in the boot sequence it often has the wrong time then adjusts near the end, prior to my Jun 07 18:38:20 main app starting Jun 07 18:43:51 zmatt I don't know why it's in that order, it's weird to me too but that's consistently what I see in /var/log/syslog Jun 07 18:44:38 even when we intentionally power-on the device it logs its boot sequence like that. Jun 07 18:46:01 okay, well rsyslog is another one of those things I don't really do anything with other than "apt-get purge" in favor of systemd-journald (which is enabled by default anyway, making rsyslog wholly redundant) Jun 07 18:46:47 not quite sure what that means. is rsyslog the thing that produces /var/log/syslog? Jun 07 18:46:51 yes Jun 07 18:47:00 is systemd-journald producing another log elsewhere? Jun 07 18:47:20 it produces journal, which you can read with systemd-journald Jun 07 18:47:43 (journal is binary format, fully indexed on all fields allowing fast filtering) Jun 07 18:47:50 oh interesting. Jun 07 18:47:55 so i might have more data to investigate with Jun 07 18:47:59 read with journalctl I mean Jun 07 18:47:59 sorry Jun 07 18:48:05 k Jun 07 18:48:19 * windsurf_ reads up on journalctl Jun 07 20:49:53 zmatt trying out journalctl and it's odd that I have about 40% of my log is from Nov and then it jumps to today Jun 07 20:50:26 more likely those first log entries are before it has remotely correct timestamps Jun 07 20:50:39 you can display monotonic timestamps instead with -o short-monotonic Jun 07 20:50:56 thx Jun 07 20:51:03 (if you're curious about all information in journal, try -o json ) Jun 07 20:56:06 yeah still same Jun 07 20:56:08 weird. Jun 07 20:57:39 maybe you're right about the bouncing times that journalctl is confused Jun 07 21:01:09 "still same" ? Jun 07 21:01:32 what do you mean? Jun 07 21:01:42 Nov 3 then jumps to July 7 Jun 07 21:01:52 log isn't as big as with /var/log/syslog Jun 07 21:02:04 where it goes from March to today with lots in between Jun 07 21:02:05 ehm, what? monotonic timestamps don't even have dates Jun 07 21:02:35 I think it was a general feeling that there was less in the file Jun 07 21:02:43 maybe i just rushed, not sure Jun 07 21:03:27 it is conceivable that syslog could manage to log more stuff right before a power failure, since journal has stronger integrity checking Jun 07 21:03:50 also I don't know whether everything goes to journal if rsyslog is present since I never have rsyslog present Jun 07 21:04:02 yeah but there are whole days worth of successful messages i wasn't seeing. Not with monotonic though Jun 07 21:04:18 i see Jun 07 21:04:20 uhh that sounds strange Jun 07 21:04:45 what systemd version are you using btw? Jun 07 21:04:51 I shouldn't comment really on monotonic. i only glanced at it Jun 07 21:05:09 i'll get back to you on that in a few, checking another device that just had the problem... Jun 07 21:05:13 -o short-monotonic doesn't change which log entries are listed nor in which order, it just changes the timestamp format Jun 07 21:05:20 ok Jun 07 21:05:49 it looked a lot like the kernel log (dmesg) so I didn't more than 30 s in there. need to look closer Jun 07 21:06:36 journal includes the kernel log, and everything else (normally anyway. like I said, I don't know which messages are routed where when rsyslog is also present) Jun 07 21:08:05 looking again, i'm definitely seeing messages from all the sources I'm used to with the syslog Jun 07 21:08:20 , using journalctl in monotonic but I can't tell which day these are from Jun 07 21:09:00 yeah monotonic timestamps are relative to boot, hence most useful when combined with -b I guess Jun 07 21:09:12 just holding page down it takes way longer to get through syslog than journalctl Jun 07 21:09:19 it was just to confirm whether "time jumps" are really timejumps Jun 07 21:09:53 yeah it's better to limit output using commandline options rather than asking journalctl to dump everything Jun 07 21:19:12 so this last reboot we just saw does have a bunch of null blocks and we didn't switch power off so maybe the problem does manifest in a couple different ways Jun 07 21:19:20 not so clean after all Jun 07 21:20:42 journalctl -b -o short-monotonic | grep recovery Jun 07 21:23:44 yes I see recovery doing that and also in the syslog after that restart Jun 07 21:24:05 evidently not a clean reboot :) maybe you just missed it earlier? Jun 07 21:24:24 like I said, I wouldn't expect the clock to be wrong after a clean reboot Jun 07 21:25:05 though if you're using an external rtc, I wouldn't expect the clock to be wrong at all period. if it's initially wrong at boot, that suggests a configuration issue Jun 07 21:26:19 I didn't miss it earlier Jun 07 21:26:26 I checked two different devices' logs Jun 07 21:26:32 weird Jun 07 21:29:56 when the power comes on and if the BB isn't online, prior to the RTC service being loaded, why would the BB have the correct time? Jun 07 21:30:20 rtc service? rtc is normally handled by the kernel Jun 07 21:30:30 or did you mean ntp server when you said rtc earlier? Jun 07 21:30:42 i created my own rtc service which sets the system time from my 3rd party rtc. Jun 07 21:31:02 ehhh Jun 07 21:31:20 you mean like an rtc connected via i2c or such? Jun 07 21:31:38 it doesn't have a kernel driver to let the kernel take care of that for you? Jun 07 21:31:39 i meant rtc though the device near the end of boot also connects to internet and does also talk to ntp server Jun 07 21:31:54 i didn't do any special configuration for how linux does what it does with ntp, that' default Jun 07 21:32:02 correct, i2c rtc Jun 07 21:32:08 which rtc? Jun 07 21:32:30 ds3231 Jun 07 21:32:51 my service performs hwclock commands Jun 07 21:33:11 yep that one has a kernel driver. if you declare its existence in your DT then the kernel will take care of everything and your system will have the correct time and date right from the start Jun 07 21:33:36 wish I knew that 6 months ago :P Jun 07 21:33:56 is that just uncommenting a line? Jun 07 21:34:20 mine mounts on /dev/rtc1 – would it be on /dev/rtc0 if I do it the kernel driver way? Jun 07 21:34:47 https://github.com/mvduin/overlay-utils/blob/master/i2c1-mcp7940x.dtsi something like that, but with compatible = "maxim,ds3231"; Jun 07 21:35:17 no I'd assume it would still be rtc1, since the built-in rtc is still present too (required to be able to power off the system) Jun 07 21:35:41 thanks. i'll check that out soon. Seems like it'll be cleaner and be less confusing – do you think it could cause my issue or just confound it? Jun 07 21:36:23 nah your way isn't causing any issue other than being unnecessarily complicated and making early boot logs harder to read Jun 07 21:37:34 gotcha. sounds like a nice cleanup task for sure. Jun 07 22:42:38 zmatt tried to reproduce by quickly grounding the reset pin. looking at the device's screen and at syslog it looks like it's doing the same thing just a reboot, no garbage this time (tried first with a longer grounding of the reset pin and I go similar results but some garbage) Jun 07 22:43:07 that doesn't help you with identifying the cause of the reset though Jun 07 22:44:34 tried it cause i wondered if it could be that interference is triggering the reset pin Jun 07 22:46:51 I doubt that even if you'd attach an antenna to the reset pin. there's so much capacitance on that net that the reset pulse driven by the processor onto that net when you do a soft-reset is completely invisible on the scope Jun 07 22:49:09 so something is "resetting" the BB just don't know what the source is yet and as you say, probably isn't literally via the reset pin Jun 07 22:49:13 (this was even true when I configured that pulse to its maximum length, 10 μs) Jun 07 22:49:53 you can check the last reset cause actually Jun 07 22:50:05 hold on Jun 07 22:59:46 cool. also looking into BB overheating potential. Jun 07 22:59:53 do you know what happens when it overheats? Jun 07 23:00:40 its longevity is reduced Jun 07 23:00:49 saw an article that showed it idles at about 60º in an 28º ambient environment when running CPU 100%. In our case it's in a warm case so it's plausible that's tipping it over but no evidence of it yet Jun 07 23:00:57 would it reboot? Jun 07 23:01:41 I don't think so actually, unless the pmic's thermal limit is triggered Jun 07 23:04:23 85ºC? Jun 07 23:04:43 no, waay higher I'm pretty sure Jun 07 23:05:00 but check its datasheet if you want to be sure Jun 07 23:06:57 Temp Range: 0 to 85°C Jun 07 23:07:02 https://octavosystems.com/docs/osd335x-sm-datasheet/ Jun 07 23:07:11 which I found from, https://newscrewdriver.com/2018/03/02/does-pocketbeagle-need-a-heat-sink-probably-not/ Jun 07 23:07:38 that's the official operating temperature range, not the thermal shutdown limit of the pmic Jun 07 23:07:46 gotcha Jun 07 23:08:04 (at least I *think* it has a thermal shutdown, if I remember correctly) Jun 07 23:10:20 https://pastebin.com/x04fX5B2 this will dump and clear the device reset status bits Jun 07 23:11:10 so you'd need to run it once before a reboot occurs to ensure those bits are cleared, otherwise the result after the spontaneous reboot is not very likely to be useful Jun 07 23:12:20 oh, thanks! Jun 07 23:13:03 so maybe put it in a service so that I see the output on the good startup then I would see it again after a bad restart to compare, good plan? Jun 07 23:13:21 yep something like that Jun 07 23:13:36 of course you're still not getting much info Jun 07 23:14:24 somehow capturing the serial console output when it happens is still your best hope I think Jun 07 23:14:56 it's pretty elusive. I've got 17 devices in the backyard just waiting for one to randomly happen within ~2h period Jun 07 23:15:28 well you hopefully only need to capture the serial output once Jun 07 23:15:51 yeah but i'd need to tether to my computer on each one until it happens right? Jun 07 23:15:59 who knows how many hours that would take of idling Jun 07 23:16:27 you could wire up pairs of them to monitor each other's serial console maybe? Jun 07 23:16:35 if you have a free uart available Jun 07 23:17:20 what are the debug serial ports you're talking about, never tried that but I remember you mentioning it before. What are the pinouts? Jun 07 23:19:07 my notes say P1.30 should be uart 0 txd Jun 07 23:19:35 but you can actually configure any uart to be the serial console Jun 07 23:21:17 on the beaglebone there's a dedicated serial console port... this isn't the case on the pocketbeagle so I don't know whether it's setup by default even Jun 07 23:21:47 well, u-boot needs one regardless, so I assume it's setup by default Jun 07 23:22:14 (you can check /proc/cmdline to confirm whether the console is indeed ttyS0 ) Jun 07 23:28:38 so P1.30 is already set up to give debug info eh? Jun 07 23:40:00 what does cold reset mean? I just booted normally and my service running your probe is printing 'cold reset' Jun 07 23:41:53 cold reset is indicate after power-up Jun 07 23:42:09 cold reset also clears other reset conditions Jun 07 23:42:52 more precisely, cold reset is triggered by the power-on-reset input (PORz) of the processor, which is driven by the PGOOD signal from the PMIC Jun 07 23:43:00 and what should I expect to see after my unexpected restart? Jun 07 23:43:22 one of the other reset conditions Jun 07 23:43:29 external reset = reset pin Jun 07 23:43:37 k cool. Jun 07 23:43:55 software warm reset = reboot by software request Jun 07 23:44:04 watchdog reset = watchdog reset Jun 07 23:44:06 :P Jun 07 23:44:27 that's pretty awesome. is watchdog about hardware interrupts / brownouts? Jun 07 23:44:53 watchdog is a timer that, when enabled, needs to be periodically reset to indicate the system is still running normally Jun 07 23:45:21 nice Jun 07 23:45:28 when used, it is typically controlled either by a watchdog daemon or by systemd Jun 07 23:45:47 it's to ensure the system reboots when it gets stuck in some way Jun 07 23:47:12 (systemd can be configured to use the watchdog via the RuntimeWatchdogSec setting in /etc/systemd/system.conf ) Jun 07 23:56:27 just got 'external warm reset' after intentionally resetting reset pin to ground using a wire. Is that the expected output? Jun 07 23:57:41 zn Jun 07 23:57:43 zmatt Jun 07 23:57:53 01:43 < zmatt> external reset = reset pin Jun 07 23:58:10 yeah but i'm getting 'external warm reset' Jun 07 23:58:14 you didn't list that specifically Jun 07 23:58:39 all resets that aren't "cold reset" are warm resets Jun 07 23:59:06 sorry for neglecting to write it out explicitly :P but you could have seen from the source code that there's no other flavor of external reset Jun 07 23:59:27 true, sorry Jun 08 00:49:51 cool, just happened again with the reset-cause installed... Jun 08 00:49:57 on two devices. checking Jun 08 00:57:10 well? Jun 08 00:57:29 almost there Jun 08 01:06:05 hm not sure the problem did occur this time,not the same one. Jun 08 01:06:26 i'll get back to you if I have anything relevant to share, sorry for the tease Jun 08 01:06:31 I'm going to sleep anyway Jun 08 01:06:41 :) thanks for today. maybe see ya tomorrow Jun 08 01:11:23 ok yes, it did happen. just confusing with my weird times. Jun 08 01:11:28 zmatt got cold reset Jun 08 01:11:42 after some null char garbage, reboot, 'cold reset'. Jun 08 01:12:08 not sure what to make of that though – except that it doesn't seem to be the reset line Jun 08 01:13:09 well it suggests the system is being power-cycled for whatever reason Jun 08 01:14:08 wonder if I should add more caps to the power supply or something Jun 08 01:45:34 zmatt btw the RuntimeWatchdogSec setting is commented out in system.conf so I think that means that there is no watchdog and that can't be the cause of a restart in my case? **** ENDING LOGGING AT Fri Jun 08 03:00:18 2018