Linux-kernel: printk from "open" syscall don't work

Question

I have a doubt.

I opened the kernel and I changed the directory linux-3.1.1/fs/open.c

I changed the follow code in the open.c.

SYSCALL_DEFINE3(open, const char __user *, filename, int, flags, int, mode)
{
    long ret;
    printk(KERN_EMERG "Testing\n");
    ... 
}

I put this line only: printk(KERN_EMERG "Testing");

And I include the libraries:<linux/kernel.h> and <linux/printk.h>

So I compiled and rebooted my linux(Ubuntu). During the rebooting appeared a lot of "Testing" on the screen. So up to now its Ok.

---

But now I have a problem. I created this program in c.

int main()
{
    size_t filedesc = open("testefile2.txt",O_CREAT | O_WRONLY,0640);
    printf("%d",filedesc);
}

I compiled this program and executed and works good. But I don´t understand why the "Testing" didn't appeared on the shell. I mean , if when I reboot the pc appeared a lot of the word "Testing" , why this word doens´t appear when I execute the program above. Just to add I include this libraries in this code above:

unistd.h , fcntl.h , stdio.h , stdlib.h

Thank you guys.

Debenture

I tried fixing the formatting on this, but it seems I made it worse. Anyone see where it's screwed up? I don't see anything wrong with the way the code blocks are formatted... :( – Benefaction

I think its better now.Sorry,I didnt know how to use this format correctly.Thank you. – Debenture

Maybe your printk() isn't appearing where you expect it to appear. When you open another virtual console (or terminal) and type sudo tail -f /var/log/dmesg, do you see your Testing messages? – Cowpox

Mike is probalby correct. Your shell is run under a different process than the console that the kernel is connected to. Ubuntu almost certainly redirects the output to the system log. – Bacchant

When I type this sudo tail -f /var/log/dmesg doesnt appear "Testing" Basically I`m open a shell and typing this:gcc -o t test.c And then : ./t But its prints only 3 – Debenture

Answer 1

But I don´t understand why the "Testing" didn't appeared on the shell.

I think, this is effect of printk's messages suppression. (more exactly:rate limiting)

Check the messages log or console for

printk: ### messages suppressed.

string.

This feature will stop printing a message, if there were a lot of messages in recent time.

Actual code is as 3.1 kernel: http://lxr.linux.no/#linux+v3.1.1/kernel/printk.c#L1621

1621 * printk rate limiting, lifted from the networking subsystem.
1622 *
1623 * This enforces a rate limit: not more than 10 kernel messages
1624 * every 5s to make a denial-of-service attack impossible.
1625 */
1626 DEFINE_RATELIMIT_STATE(printk_ratelimit_state, 5 * HZ, 10);
1627
1628 int __printk_ratelimit(const char *func)

So, As the open syscall is very-very popular (just do an strace -e open /bin/ls - I'll get 15 open syscalls for just starting an simplest ls), the rate limiting will be in effect. It will limit your message to be printed only one time in 5 seconds; not more than 10 messages in single "burst".

I can only suggest to create a special user with known UID and add an UID checking before printk in your additional printk-in-open code.

Betts

In fact , I want that the shell prints the word "Testing",because I want to do some tests with system call. Thank you for your answer. – Debenture

Sorry , I think understood the comment now. – Debenture

message from printk will not be printed by shell. It is printed by kernel on some text console (which is opened by Alt-F1) and also saved in dmesg buffer and also sent to syslog daemon. You just doing more printk, than is allowed to be printed. You should add some condition before printk, because open is one of most used syscall. You should only printk for case you are interested in, e.g. by testing UID or path. – Betts

Well,Could you suggest me what I can put before printk(KERN_EMERG "Testing\n") to show the "Testing"? I didnt understand so well what I can put in the code.Thanks – Debenture

[ 24.295775] audit_printk_skb: 30 callbacks suppressed Is this the problem? – Debenture

if(current->uid == YOUR_SPECIAL_UID) { printk(...);} and also you can lower limits in /kernel/printk.c file at DEFINE_RATELIMIT_STATE(printk_ratelimit_state, 5 * HZ, 10). Change it to ... DEFINE_RATELIMIT_STATE(printk_ratelimit_state, HZ, 100) - it is 100 messages per second limit. Do both changes. The 30 callbacks suppressed is not a problem, it just says that there are a lot of messages generated by your printk, and the problem is very high rate of printk messages. – Betts

Answer 2

printk calls appear in the kernel message buffer, not in your process' stdout/stderr

Kreiner

Could you tell me how I open the kernel message buffer and see the word "Testing"? Because I am not "finding" it.Thank you. – Debenture

@Debenture use the 'dmesg' command, or look in one of the syslog logs (under /var/log/ ) – Lvov