real-time Ubuntu 12.04 eventually fills up SD card with log files!

[wally_666]

I left my real-time Ubuntu 12.04  Pandaboard ES  system ( setup uisng these instructions: https://groups.google.com/forum/#!topic/robotreferenceplatform/HqgJK-RyAbY ) running over the thanksgiving holiday and shortly thereafter the system behaved strangely and ultimately locked up!

My solution was to put the SD card into my development system and delete the SWAP.swap hidden file and all the log files and their *.gz "archives in var/log

Things are working fine now, but the df  command shows disk usage is growing way out of proportion to my usage.

The real solution lies in Ubuntu configuration land, but if anyone knows, it'd be good to post it here.  

I'll do so if/when I figure out a solution, if nobody posts an answer here.

in the meantime, be aware that potential disaster lurks because of this for any long running robot!

--wally.

[Austin Hendrix]

Is it log files that continue to use space, or is there something else going on?

Rather than just delete the log files, I suggest you read them to see what the problem is and maybe figure out what you can do to correct it. It may be as simple as turning down the logging verbosity on something and/or adjusting the log rotation settings.

-Austin

[wally_666]

The system was totally idle over the holidays yet manged to fill up the SD card with ~4GB of log files, obviously the logging settings are not suitable for a system with such limited resources, they seem to be on a "weekly" rotation,  Daily would probably be better.

As far as I know I'm using the default settings from the system installed using the tutorial instructions., which is why I posted here.  I'm not running a robot, so nothing bad happens when my system crashes because of it.  If you reboot every day, you may never see the problem.

"Turning down the logging verbosity" is exactly what I'm looking for learning how to do!  Haven't had a chance to search the Ubuntu forums yet, maybe tonight or tomorrow.

Like anyone has got time to read ~4GB of logfile jabber.

They are full of such enlightenment as:

[74059.502070] [<c00bd018>] (irq_forced_thread_fn+0x30/0x6c) from [<c00bce08>] (irq_thread+0xac/0x16c)

[74059.502093] [<c00bce08>] (irq_thread+0xac/0x16c) from [<c006431c>] (kthread+0x9c/0xa8)

[74059.502118] [<c006431c>] (kthread+0x9c/0xa8) from [<c00142e8>] (kernel_thread_exit+0x0/0x8)

[74059.502128] Mem-info:

[74059.502134] Normal per-cpu:

[74059.502142] CPU    0: hi:  186, btch:  31 usd: 180

[74059.502150] CPU    1: hi:  186, btch:  31 usd: 167

[74059.502166] active_anon:5706 inactive_anon:2326 isolated_anon:0

[74059.502170]  active_file:62839 inactive_file:71969 isolated_file:0

[74059.502175]  unevictable:0 dirty:5124 writeback:1 unstable:0

[74059.502179]  free:3254 slab_reclaimable:22755 slab_unreclaimable:2103

[74059.502184]  mapped:2844 shmem:2377 pagetables:231 bounce:0

[74059.502208] Normal free:13016kB min:8192kB low:10240kB high:12288kB active_anon:22824kB inactive_anon:9304kB active_file:251356kB inactive_file:287876kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:713792kB mlocked:0kB dirty:20496kB writeback:4kB mapped:11376kB shmem:9508kB slab_reclaimable:91020kB slab_unreclaimable:8412kB kernel_stack:1016kB pagetables:924kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no

[74059.502232] lowmem_reserve[]: 0 0

[74059.502244] Normal: 3120*4kB 47*8kB 8*16kB 1*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 13016kB

[74059.502281] 137186 total pagecache pages

[74059.502287] 0 pages in swap cache

[74059.502294] Swap cache stats: add 0, delete 0, find 0/0

[74059.502301] Free swap  = 0kB

[74059.502307] Total swap = 0kB

[74059.517032] 180224 pages of RAM

[74059.517043] 3911 free pages

[74059.517049] 6513 reserved pages

[74059.517054] 24857 slab pages

[74059.517060] 132284 pages shared

[74059.517066] 0 pages swap cached

[74059.517076] SLAB: Unable to allocate memory on node 0 (gfp=0x20)

[74059.517086]   cache: size-32768, object size: 32768, order: 3

[74059.517101]   node 0: slabs: 14/14, objs: 14/14, free: 0

[74064.980699] irq/109-ehci_hc: page allocation failure: order:3, mode:0x20

[74064.980742] [<c001b858>] (unwind_backtrace+0x0/0xec) from [<c05fa764>] (dump_stack+0x20/0x24)

[74064.980769] [<c05fa764>] (dump_stack+0x20/0x24) from [<c00fb0a8>] (warn_alloc_failed+0xfc/0x11c)

[74064.980788] [<c00fb0a8>] (warn_alloc_failed+0xfc/0x11c) from [<c00fdaa8>] (__alloc_pages_nodemask+0x65c/0x780)

[74064.980806] [<c00fdaa8>] (__alloc_pages_nodemask+0x65c/0x780) from [<c05fce84>] (cache_alloc_refill+0x2f8/0x65c)

[74064.980826] [<c05fce84>] (cache_alloc_refill+0x2f8/0x65c) from [<c012fe60>] (__kmalloc_track_caller+0x114/0x254)

[74064.980848] [<c012fe60>] (__kmalloc_track_caller+0x114/0x254) from [<c04f618c>] (__alloc_skb+0x60/0xfc)

[74064.980865] [<c04f618c>] (__alloc_skb+0x60/0xfc) from [<c04f669c>] (__netdev_alloc_skb+0x2c/0x54)

[74064.980882] [<c04f669c>] (__netdev_alloc_skb+0x2c/0x54) from [<c04093d8>] (rx_submit+0x2c/0x1d4)

[74064.980898] [<c04093d8>] (rx_submit+0x2c/0x1d4) from [<c04099cc>] (rx_complete+0x190/0x1b4)

[74064.980917] [<c04099cc>] (rx_complete+0x190/0x1b4) from [<c04111ec>] (usb_hcd_giveback_urb+0xb0/0xfc)

[74064.980940] [<c04111ec>] (usb_hcd_giveback_urb+0xb0/0xfc) from [<c0423890>] (ehci_urb_done+0xbc/0xcc)

[74064.980957] [<c0423890>] (ehci_urb_done+0xbc/0xcc) from [<c0425af8>] (qh_completions+0xbc/0x528)

[74064.980972] [<c0425af8>] (qh_completions+0xbc/0x528) from [<c0427c00>] (ehci_work+0xac/0x940)

[74064.980987] [<c0427c00>] (ehci_work+0xac/0x940) from [<c042a6e8>] (ehci_irq+0x35c/0x3c8)

[74064.981002] [<c042a6e8>] (ehci_irq+0x35c/0x3c8) from [<c042a7a8>] (ehci_omap_irq+0x54/0x58)

[74064.981017] [<c042a7a8>] (ehci_omap_irq+0x54/0x58) from [<c04108d0>] (usb_hcd_irq+0x38/0x4c)

[74064.981036] [<c04108d0>] (usb_hcd_irq+0x38/0x4c) from [<c00bd018>] (irq_forced_thread_fn+0x30/0x6c)

[74064.981054] [<c00bd018>] (irq_forced_thread_fn+0x30/0x6c) from [<c00bce08>] (irq_thread+0xac/0x16c)

[74064.981077] [<c00bce08>] (irq_thread+0xac/0x16c) from [<c006431c>] (kthread+0x9c/0xa8)

[74064.981101] [<c006431c>] (kthread+0x9c/0xa8) from [<c00142e8>] (kernel_thread_exit+0x0/0x8)

[74064.981111] Mem-info:

[74064.981117] Normal per-cpu:

[74064.981125] CPU    0: hi:  186, btch:  31 usd: 173

[74064.981134] CPU    1: hi:  186, btch:  31 usd: 164

[74064.981149] active_anon:5706 inactive_anon:2332 isolated_anon:0

[74064.981154]  active_file:62839 inactive_file:71953 isolated_file:0

[74064.981158]  unevictable:0 dirty:5130 writeback:0 unstable:0

[74064.981163]  free:3287 slab_reclaimable:22754 slab_unreclaimable:2094

[74064.981167]  mapped:2844 shmem:2377 pagetables:231 bounce:0

[74064.981191] Normal free:13148kB min:8192kB low:10240kB high:12288kB active_anon:22824kB inactive_anon:9328kB active_file:251356kB inactive_file:287812kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:713792kB mlocked:0kB dirty:20520kB writeback:0kB mapped:11376kB shmem:9508kB slab_reclaimable:91016kB slab_unreclaimable:8376kB kernel_stack:1016kB pagetables:924kB unstable:0kB 

[Austin Hendrix]

That looks like an excerpt from the kernel log and it looks like you're
having memory problems; in particular this line stands out:

[74059.517076] SLAB: Unable to allocate memory on node 0 (gfp=0x20)

I plugged that into google and found a reasonable explanation:
http://freejabber.com/2012/07/26/avoid-linux-page-allocation-failures-by-adjusting-virtual-memory-configuration/

Logfile "jabber" is often quite repetitive; don't read it like a novel,
just skim through it looking for patterns and high-frequency messages.
Logs grow from the end, so use tail to inspect the end of a log file,
and tail -f to watch log file activity.

-Austin

> <javascript:>> wrote:
>
>> I left my real-time Ubuntu 12.04 Pandaboard ES system ( setup
>> uisng these instructions:
>> https://groups.google.com/forum/#!topic/robotreferenceplatform/HqgJK-RyAbY

>> <https://groups.google.com/forum/#%21topic/robotreferenceplatform/HqgJK-RyAbY> ) running