Pwnagotchi: the OS ran out of memory

[mrseeker]

Describe the bug
When the pwnagotchi runs for too long, it will eventually run into issues where there is literally too much memory being used, and eventually it will crash and die, as in "won't respond". There is no way to notice that this is happening, nor does it try to reset itself.

To Reproduce
Steps to reproduce the behavior:
Run the pwnagotchi for over 10h straight in AI mode (around 150k-175k log).

Expected behavior
When the pwnagotchi detects it runs out of memory, either do proper garbage collection or kill itself...

Environment (please complete the following information):

• Pwnagotchi: version 1.2.1 (latest stable)
• OS version: Unknown (latest stable)
• Type of hardware: Raspi Zero W
• Any additional hardware used: Sharewave screen (default setup)

Additional context

Logfile is >100mb, will only show relevant parts below:

[2019-11-11 15:39:05,694] [INFO] [ai] setting new policy:
[2019-11-11 15:39:08,171] [INFO] [ai] --- training epoch 17/50 ---
[2019-11-11 15:39:09,064] [INFO] [ai] REWARD: -0.001730
[2019-11-11 15:39:09,129] [INFO] [ai] observation:
[2019-11-11 15:39:09,149] [INFO]     aps
[2019-11-11 15:39:09,153] [INFO]       CH 1: 0.08333333333263888
[2019-11-11 15:39:09,172] [INFO]       CH 3: 0.08333333333263888
[2019-11-11 15:39:09,200] [INFO]       CH 4: 0.16666666666527777
[2019-11-11 15:39:09,204] [INFO]       CH 6: 0.49999999999583333
[2019-11-11 15:39:09,239] [INFO]       CH 11: 0.16666666666527777
[2019-11-11 15:39:09,254] [INFO]     sta
[2019-11-11 15:39:09,290] [INFO]     peers
[2019-11-11 15:39:09,299] [INFO] [ai] saving model to /root/brain.nn ...
[2019-11-11 15:39:10,199] [INFO] [ai] saving /root/brain.json
[2019-11-11 15:39:10,820] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:10,852] [ERROR] main loop exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 8, in decode
    return r.json()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 897, in json
    return complexjson.loads(self.text, **kwargs)
  File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 518, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
    obj, end = self.raw_decode(s)
  File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/bin/pwnagotchi", line 95, in <module>
    agent.recon()
  File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/agent.py", line 149, in recon
    self.run('wifi.recon.channel clear')
  File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 40, in run
    return decode(r, verbose_errors=verbose_errors)
  File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 16, in decode
    raise Exception(err)
Exception: error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:11,530] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:11,565] [ERROR] main loop exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 8, in decode
    return r.json()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 897, in json
    return complexjson.loads(self.text, **kwargs)
  File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 518, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
    obj, end = self.raw_decode(s)
  File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

[yecukeng]

+1 for this issue. I have exactly the same behavior on RPi 0 W. It can
occur in 2-3 hours if there is a lot of networks around.

On Mon, Nov 11, 2019, 22:28 Julius ter Pelkwijk [e-mail]
wrote:

Describe the bug
When the pwnagotchi runs for too long, it will eventually run into issues
where there is literally too much memory being used, and eventually it will
crash and die.

To Reproduce
Steps to reproduce the behavior:
Run the pwnagotchi for over 10h straight in AI mode (around 150k-175k log).

Expected behavior
When the pwnagotchi detects it runs out of memory, either do proper
garbage collection or kill itself...

Environment (please complete the following information):

• Pwnagotchi: version 1.2.1 (latest stable)
• OS version: Unknown (latest stable)
• Type of hardware: Raspi Zero W
• Any additional hardware used: Sharewave screen (default setup)

Additional context

Logfile is >100mb, will only show relevant parts below:

[2019-11-11 15:39:05,694] [INFO] [ai] setting new policy:
[2019-11-11 15:39:08,171] [INFO] [ai] --- training epoch 17/50 ---
[2019-11-11 15:39:09,064] [INFO] [ai] REWARD: -0.001730
[2019-11-11 15:39:09,129] [INFO] [ai] observation:
[2019-11-11 15:39:09,149] [INFO] aps
[2019-11-11 15:39:09,153] [INFO] CH 1: 0.08333333333263888
[2019-11-11 15:39:09,172] [INFO] CH 3: 0.08333333333263888
[2019-11-11 15:39:09,200] [INFO] CH 4: 0.16666666666527777
[2019-11-11 15:39:09,204] [INFO] CH 6: 0.49999999999583333
[2019-11-11 15:39:09,239] [INFO] CH 11: 0.16666666666527777
[2019-11-11 15:39:09,254] [INFO] sta
[2019-11-11 15:39:09,290] [INFO] peers
[2019-11-11 15:39:09,299] [INFO] [ai] saving model to /root/brain.nn ...
[2019-11-11 15:39:10,199] [INFO] [ai] saving /root/brain.json
[2019-11-11 15:39:10,820] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:10,852] [ERROR] main loop exception
Traceback (most recent call last):
File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 8, in decode
return r.json()
File "/usr/lib/python3/dist-packages/requests/models.py", line 897, in json
return complexjson.loads(self.text, **kwargs)
File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 518, in loads
return _default_decoder.decode(s)
File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
obj, end = self.raw_decode(s)
File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/usr/local/bin/pwnagotchi", line 95, in
agent.recon()
File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/agent.py", line 149, in recon
self.run('wifi.recon.channel clear')
File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 40, in run
return decode(r, verbose_errors=verbose_errors)
File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 16, in decode
raise Exception(err)
Exception: error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:11,530] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory
[2019-11-11 15:39:11,565] [ERROR] main loop exception
Traceback (most recent call last):
File "/usr/local/lib/python3.7/dist-packages/pwnagotchi/bettercap.py", line 8, in decode
return r.json()
File "/usr/lib/python3/dist-packages/requests/models.py", line 897, in json
return complexjson.loads(self.text, **kwargs)
File "/usr/lib/python3/dist-packages/simplejson/__init__.py", line 518, in loads
return _default_decoder.decode(s)
File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 370, in decode
obj, end = self.raw_decode(s)
File "/usr/lib/python3/dist-packages/simplejson/decoder.py", line 400, in raw_decode
return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/evilsocket/pwnagotchi/issues/582?email_source=notifications&email_token=ANT4HS4PXEBOZ575TTFFIITQTGW6TA5CNFSM4JLZYYDKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4HYQAN7A,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/ANT4HS53HOSXIJCSXKNLOCLQTGW6TANCNFSM4JLZYYDA
.

[mrseeker]

Another thing I noticed, and unsure if it's related to this or because I have some terrible cables (not likely), is that after a while the screen starts to show some form of corruption (pixels going darker). If I do a full refresh of the screen (by restarting the Pwnagotchi) that effect seems to go away.

[evilsocket]

If you read:

Exception: error 400: fork/exec /sbin/iwlist: cannot allocate memory

It's iwlist failing ... I can (maybe) force the GC to run for the python process, but i can't do much about the rest of the system ...

[mrseeker]

Python does not work with GC, that one only reallocates memory, but does not release it to the general population.

I think that self._history is growing too large (I had around 400 "friends" in less than 24h). That means that for every AP you encounter, it will store it's ESSID and BSSID in memory. To counter this, I propose the following:

1. Don't store names in _history but only the BSSID (reduces the pointer to 12 characters)
2. Convert the BSSID into an hexadecimal number (even more reduction on storage)
3. You can even reduce it even further by only storing the last 3 octets only (no vendor code). This "might" cause collisions, but they are rare and it also reduces the memory load even further...

[evilsocket]

i'm not sure that's the problem, 400 APs in memory are like what? even at 1000 bytes each that's less than 1M ... and SSID + BSSID are not even 100 bytes.

[andrewbeard]

iwlist is failing to launch, but that doesn't mean it's the process that is exhausting the system memory. Any chance you can post the OOM killer message from /var/log/syslog? It may help point at the process that's actually the culprit.

I've seen the same thing on a pi0 after an extended runtime (18 hours+), but it's doesn't seem to happen consistently at all. I've run for easily twice that without an issues. When I saw it happen it seemed like it was either a python script or bettercap that were hogging memory.

[evilsocket]

@andrewbeard yes of course not saying it's iwlist, just saying it's just an OS OOM and we should understand which process is causing it and why :D 400 APs in memory don't justify the OOM

[mrseeker]

Any chance you can post the OOM killer message from /var/log/syslog?

I downloaded the syslog, but not at the laptop at the moment. Will do that when I get home.

[mrseeker]

Okay, went through the whole thing, could not find any signs of an OoM.

I did however notice that the memory is at 80-90% before it crashes, which means another process is hogging memory, or I overextended the brain of my pwnagotchi. I have no clue why it would hog 40% when in AI mode, and goes all the way to 90% before crashing?

I also found out that pwngrid is constantly trying to enroll itself, to the point where it literally tries to DDoS the network:

2019-11-04 23:13:46 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.009824s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:38576->8.8.8.8:53: i/o timeout
2019-11-04 23:13:46 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:38576->8.8.8.8:53: i/o timeout
2019-11-04 23:13:59 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.005625s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51448->8.8.8.8:53: i/o timeout
2019-11-04 23:13:59 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51448->8.8.8.8:53: i/o timeout
2019-11-04 23:14:11 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.010853s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:53151->8.8.8.8:53: i/o timeout
2019-11-04 23:14:11 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:53151->8.8.8.8:53: i/o timeout
2019-11-04 23:14:24 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.011995s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:36453->8.8.8.8:53: i/o timeout
2019-11-04 23:14:24 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:36453->8.8.8.8:53: i/o timeout
2019-11-04 23:14:35 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.013257s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:36278->8.8.8.8:53: i/o timeout
2019-11-04 23:14:35 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:36278->8.8.8.8:53: i/o timeout
2019-11-04 23:14:48 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.007573s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:43815->8.8.8.8:53: i/o timeout
2019-11-04 23:14:48 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:43815->8.8.8.8:53: i/o timeout
2019-11-04 23:14:59 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.005228s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:33631->8.8.8.8:53: i/o timeout
2019-11-04 23:14:59 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:33631->8.8.8.8:53: i/o timeout
2019-11-04 23:15:13 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.007646s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:43000->8.8.8.8:53: i/o timeout
2019-11-04 23:15:13 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:43000->8.8.8.8:53: i/o timeout
2019-11-04 23:15:24 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.006116s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51586->8.8.8.8:53: i/o timeout
2019-11-04 23:15:24 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51586->8.8.8.8:53: i/o timeout
2019-11-04 23:15:37 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.008823s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51411->8.8.8.8:53: i/o timeout
2019-11-04 23:15:37 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:51411->8.8.8.8:53: i/o timeout
2019-11-04 23:15:48 err POST https://api.pwnagotchi.ai/api/v1/unit/enroll (10.011491s) Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:59235->8.8.8.8:53: i/o timeout
2019-11-04 23:15:48 err error while refreshing token: Post https://api.pwnagotchi.ai/api/v1/unit/enroll: dial tcp: lookup api.pwnagotchi.ai on 8.8.8.8:53: read udp 10.0.0.2:59235->8.8.8.8:53: i/o timeout

Turning off the grid plugin, but need to find a way to pinpoint this memory hogging...

[mrseeker]

Looks like the grid plugin was the culprit. After I turned it off, the pwnagotchi seems to be stable at 70-80%. Looking at ways to reduce footprint on Tensorflow...

[evilsocket]

mmm that's interesting, looking into it 👍

[evilsocket]

@mrseeker i've released pwngrid v1.10.3 with a fix, can you update, enable the grid plugin and see if the issue still happens?

[xenDE]

only an other out of memory i had for documentation:

[2019-11-13 06:17:24,432] [ERROR] error connecting to the pwngrid-peer service: [Errno 12] Cannot allocate memory

i needed to reboot

[mrseeker]

@evilsocket Was already wondering why the pwnagotchi suddenly went X__X on me, but will try the fix and see if that helps :)

[mrseeker]

Well, pwnagotchi is grinding for almost 10h without slowing down. Will have to check later if it holds up to any scrutiny, but at this moment I am positive this was the main cause for the issues I was seeing.

[evilsocket]

@mrseeker that's great, let me know if the problem arises again or if we can close this finally :D

[mrseeker]

Closing this ticket, as the pwnagotchi is running for 14h without any sign of memory issues.

[evilsocket]

FUCK YEAH

[msaratov]

Unfortunately, I am experiencing this (or a similar issue) on v1.10.3 since this morning. My pwnagotchi never leaves AUTO mode but freezes before. The logs shows:

[019-12-05 20:14:32,045] [INFO] grid: 536 new networks to report
[2019-12-05 20:14:42,369] [INFO] grid: parsing /root/handshakes/LH***.pcap ...
[2019-12-05 20:17:31,981] [INFO] grid: 536 new networks to report
[2019-12-05 20:17:35,272] [INFO] grid: parsing /root/handshakes/LH****.pcap ...
[2019-12-05 20:19:54,388] [ERROR] error connecting to the pwngrid-peer service: [Errno 12] Cannot allocate memory
[2019-12-05 20:23:25,234] [ERROR] error connecting to the pwngrid-peer service: [Errno 12] Cannot allocate memory

This is after applying https://github.com/evilsocket/pwnagotchi/pull/658 manually by editing grid.py and clearing .api-report.json.

[xenDE]

i'm on pwngrid 1.10.3 and pwnagotchi master, but have back:

[2019-12-13 07:47:23,973] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory

any ide how i can add an auto-reboot for this?

parsing log file all 10 min? (bad)
check for freemem all 10min? (bad)
a hook on writing log and parse for " cannot allocate memory"? (hmm)

any ideas?

[epantke]

i'm also on pwngrid 1.10.3 and pwnagotchi master (5d8d862) and experiencing that OOM issue after around 20h+:

[2020-04-07 17:35:52,626] [INFO] error 400: fork/exec /sbin/iwlist: cannot allocate memory

Apr 7 17:35:52 weeduino bettercap-launcher[292]: [17:35:52] [sys.log] [war] wifi error while hopping to channel 6: fork/exec /sbin/iwconfig: cannot allocate memory

after checking the syslog and the other logfiles i still dont really know what the cause for this memory issue is. the swap memory was at 100% used while the system memory was at ~90% before it started reporting this errors.

anyone got ideas what is causing this issue?

[epantke]

@dadav could you please open this issue again so that the community can look into this since some users are experiencing this behavior again :)

[Baallrog]

I have the same problem.
It appears that there was no space left on device.
I flushed the log files, there was almost 3 go of log ... On à 8go sdcard ...