traceOpen() created a file, but trace() and traceln() couldn't write message into the file

[yusuke.sato.zz]

I am using byteman to trace call stack in JGit on Windows 10.

I wrote a byteman rule to trace start of a method like this:

RULE CheckoutCommand Start
CLASS org.eclipse.jgit.api.CheckoutCommand
METHOD call
AT ENTRY
IF true
DO
  traceOpen("log","D:/tmp/byteman_" + java.net.InetAddress.getLocalHost().getHostName() + "_" + java.time.ZonedDateTime.now().format(java.time.format.DateTimeFormatter.ISO_LOCAL_DATE) + ".log");
  trace("log", java.time.ZonedDateTime.now().format(java.time.format.DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSS")) + "\t" +$0.getRepository().getDirectory().getParentFile().getName() + "\t");
  traceln("log", "[Start][checkout] Start checkout branch: " + $0.name);
  traceClose("log");
ENDRULE

This rule was loaded successfully (When I run Eclipse from ".\eclipsec.exe -debug -consoleLog", a message "Installed rule using default helper : CheckoutCommand Start" is shown in the console), and a file like "D:/tmp/byteman_MyComputer_2019-10-30.log" was created.

But the trace message specified in trace() and traceln() was not written into that file.

I can write these message into console with debug() method, so I think the message itself has no problem.

Additionaly, the rule can wrote the message into file successfully, at another computer. Both machines run Windows 10 and use JDK 1.8.0.

How can I investigate the cause of this problem?

[adinn]

Hi Yusuke,

yusuke.sato.zz  wrote:

. . .

I can write these message into console with debug() method, so I think the message itself has no problem.

Additionaly, the rule can wrote the message into file successfully, at another computer. Both machines run Windows 10 and use JDK 1.8.0.

How can I investigate the cause of this problem?

Well, that's certainly very strange behaviour.

If this works via the console and if you can get this to work on one computer but not another then it sounds like this is not a Byteman problem but something to do with how the operating system is handling file create/write/close operations. Byteman just uses standard Java file APIs to implement the trace and traceln operations so it is not going to do anythign different on one machine to what it does on another machine. I don't know how to explain why this is failing because of anything Byteman might be doing.

Is it possible that the file system on the failing machine imposes some limits on write access or disk usage? Could the disk be full? I am sorry that I cannot really explain this result. I have only limited knowledge of Windows. Perhaps another Windows user can help?

regards,

Andrew Dinn

[jaikiran]

I'm not a Windows user either, but I think one thing to check is if there's any anti-virus or firewall kind of softwares running on the system where you see this issues. I still can't explain why that would allow the file creation to happen but not the file writes, but I have seen weird issues reported in these forums on Windows when the anti-virus/firewall software have been running. Disabling them usually helped get past the issue.

[jaikiran]

Actually, this issue got me curious. So I decided to take a look at the Byteman source code. I think this is a bug in a recent version(s) of Byteman. And that can probably explain why it works on one setup and not on another - perhaps they are using different versions of Byteman.

adinn, I think a recent change unintentionally seems to have introduced a bug in dotraceln(Object identifier, String message) and few other variants of these methods. For example, take a look at this one byteman/Helper.java at master · bytemanproject/byteman · GitHub . It checks if there is an already created PrintStream (in Yusuke's case there will be one, because of their previous call to traceOpen). If PrintStream is null that code tries to create one and then write and flush that stream. However, if PrintStream is not null, that method just returns true instead of doing any writes at all. The bug in this and few other methods has to do with the if block statement accidentally including even the write/flush calls inside it.

[adinn]

Hi Jaikiran,

adinn , I think a recent change unintentionally seems to have introduced a bug in dotraceln(Object identifier, String message) and few other variants of these methods. For example, take a look at this one byteman/Helper.java at master · bytemanproject/byteman · GitHub . It checks if there is an already created PrintStream (in Yusuke's case there will be one, because of their previous call to traceOpen). If PrintStream is null that code tries to create one and then write and flush that stream. However, if PrintStream is not null, that method just returns true instead of doing any writes at all. The bug in this and few other methods has to do with the if block statement accidentally including even the write/flush calls inside it.

Oops. Yes, you are right. This is definitely borked.

Thanks very much for looking into this. I'll push a fix and try to get a new release out soon.

regards,

Andrew Dinn

[adinn]

I created BYTEMAN-387 to deal wiht this error.

[yusuke.sato.zz]

Andrew and Jaikiran,

Thank you for your advice. The machine with no error used Byteman 4.0.7, and the machine with error used Byteman 4.0.8. As you mentiond, it looks the changes in Byteman 4.0.8 causes this problem. I will workaround the bug by downgrade Byteman to 4.0.7.

[adinn]

Thanks very much for confirming that. I am just writing a unit test for the bug fix. So, it should be sorted out in the next release.

regards,

Andrew Dinn